diff --git a/src/pipeline/pipeline.rs b/src/pipeline/pipeline.rs index caeff58..67285e8 100644 --- a/src/pipeline/pipeline.rs +++ b/src/pipeline/pipeline.rs @@ -1,6 +1,7 @@ use std::collections::HashMap; use anyhow::Result; +use tracing::debug; use super::step::PipelineStep; use crate::config::OutputType; @@ -118,7 +119,12 @@ impl Pipeline { pub fn run_steps(&self, input: String) -> Result { let mut current = input; for step in &self.steps { + let name = step.name(); + debug!(step = %name, "Starting pipeline step"); + let start = std::time::Instant::now(); current = step.execute(current)?; + let elapsed = start.elapsed(); + debug!(step = %name, duration_ms = elapsed.as_millis(), "Pipeline step completed"); } Ok(current) } @@ -129,8 +135,20 @@ impl Pipeline { /// `input → transforms → steps`. It is equivalent to calling /// [`Pipeline::run_transforms`] followed by [`Pipeline::run_steps`]. pub fn run(&self, input: String) -> Result { + let transform_start = std::time::Instant::now(); let transformed = self.run_transforms(input)?; - self.run_steps(transformed) + let transform_elapsed = transform_start.elapsed(); + debug!(duration_ms = transform_elapsed.as_millis(), "Transform phase completed"); + + let steps_start = std::time::Instant::now(); + let result = self.run_steps(transformed)?; + let steps_elapsed = steps_start.elapsed(); + debug!(duration_ms = steps_elapsed.as_millis(), "Step phase completed"); + + let total_elapsed = transform_start.elapsed(); + debug!(duration_ms = total_elapsed.as_millis(), "Pipeline execution completed"); + + Ok(result) } } @@ -421,4 +439,49 @@ mod tests { // AlwaysFails is skipped and its input is passed through unchanged. assert_eq!(result.unwrap(), "plain text"); } + + // ── Timing and performance tracing tests ───────────────────────────────── + + #[test] + fn test_step_default_name_is_pipeline_step() { + let step = AppendStep(" x".to_string()); + assert_eq!(step.name(), "PipelineStep"); + } + + #[test] + fn test_step_custom_name() { + struct NamedStep; + impl PipelineStep for NamedStep { + fn name(&self) -> &str { + "NamedStep" + } + fn execute(&self, input: String) -> Result { + Ok(input) + } + } + let step = NamedStep; + assert_eq!(step.name(), "NamedStep"); + } + + #[test] + fn test_run_steps_completes_and_returns_correct_output() { + // Verifies that adding timing instrumentation didn't break run_steps correctness. + let mut pipeline = Pipeline::new(); + pipeline + .add_step(Box::new(AppendStep(" a".to_string()))) + .add_step(Box::new(AppendStep(" b".to_string()))); + let result = pipeline.run_steps("start".to_string()).unwrap(); + assert_eq!(result, "start a b"); + } + + #[test] + fn test_run_pipeline_timing_does_not_affect_output() { + // Verifies that the timing wrappers in run() don't alter correctness. + let mut pipeline = Pipeline::new(); + pipeline + .add_transform(Box::new(AppendTransform(" t".to_string()))) + .add_step(Box::new(AppendStep(" s".to_string()))); + let result = pipeline.run("input".to_string()).unwrap(); + assert_eq!(result, "input t s"); + } } diff --git a/src/pipeline/step.rs b/src/pipeline/step.rs index 0d0fc86..35aa395 100644 --- a/src/pipeline/step.rs +++ b/src/pipeline/step.rs @@ -1,5 +1,13 @@ use anyhow::Result; pub trait PipelineStep { + /// Human-readable name for this step, used in log messages and performance traces. + /// + /// Override this in concrete step types to make timing diagnostics more + /// actionable (e.g. `"HtmlStep"` instead of the generic `"PipelineStep"`). + fn name(&self) -> &str { + "PipelineStep" + } + fn execute(&self, input: String) -> Result; } diff --git a/src/pipeline/strategy_step.rs b/src/pipeline/strategy_step.rs index f837f5c..535c3e7 100644 --- a/src/pipeline/strategy_step.rs +++ b/src/pipeline/strategy_step.rs @@ -83,6 +83,10 @@ impl StrategyStep { } impl PipelineStep for StrategyStep { + fn name(&self) -> &str { + "StrategyStep" + } + fn execute(&self, input: String) -> Result { info!(output = %self.output_path, "Executing strategy step"); let temp_file = TempFile::with_content(input.as_bytes())?; @@ -276,4 +280,10 @@ mod tests { assert_eq!(result, "Hello [emoji] World"); assert!(!result.contains('😀'), "emoji should have been replaced by the transform"); } + + #[test] + fn test_strategy_step_name() { + let step = make_step(Box::new(AlwaysOkStrategy), "/tmp/out.html"); + assert_eq!(step.name(), "StrategyStep"); + } } diff --git a/src/transforms/registry.rs b/src/transforms/registry.rs index 75b5d98..322c41e 100644 --- a/src/transforms/registry.rs +++ b/src/transforms/registry.rs @@ -80,6 +80,7 @@ impl TransformRegistry { let name = transform.name(); debug!(transform = %name, "Starting transform"); + let start = std::time::Instant::now(); if self.failure_mode == FailureMode::FailFast { current = transform .apply(current) @@ -109,8 +110,8 @@ impl TransformRegistry { } } } - - debug!(transform = %name, "Transform completed"); + let elapsed = start.elapsed(); + debug!(transform = %name, duration_ms = elapsed.as_millis(), "Transform completed"); } Ok(current) }