From f904648883a17064e595f155c61513f608fc3899 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 11 Apr 2026 10:52:30 +0000 Subject: [PATCH 1/3] Initial plan From 714edf08c5f9bfedaf1a0599c8a0cc5817ea1989 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 11 Apr 2026 10:56:48 +0000 Subject: [PATCH 2/3] feat: add pipeline execution timing and performance tracing Agent-Logs-Url: https://github.com/egohygiene/renderflow/sessions/188aa807-4774-45ff-a290-d8c38fa04be6 Co-authored-by: szmyty <14865041+szmyty@users.noreply.github.com> --- src/pipeline/pipeline.rs | 67 ++++++++++++++++++++++++++++++++++- src/pipeline/step.rs | 8 +++++ src/pipeline/strategy_step.rs | 10 ++++++ src/transforms/registry.rs | 5 +-- 4 files changed, 87 insertions(+), 3 deletions(-) diff --git a/src/pipeline/pipeline.rs b/src/pipeline/pipeline.rs index caeff58..c1a7a3d 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,22 @@ 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 pipeline_start = std::time::Instant::now(); + + 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 = pipeline_start.elapsed(); + debug!(duration_ms = total_elapsed.as_millis(), "Pipeline execution completed"); + + Ok(result) } } @@ -421,4 +441,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) } From a644926f1fe1fdf6b57e1a99d3abd2da98b67f26 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 11 Apr 2026 11:01:04 +0000 Subject: [PATCH 3/3] refactor: reuse transform_start as pipeline reference point to eliminate measurement gap Agent-Logs-Url: https://github.com/egohygiene/renderflow/sessions/188aa807-4774-45ff-a290-d8c38fa04be6 Co-authored-by: szmyty <14865041+szmyty@users.noreply.github.com> --- src/pipeline/pipeline.rs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/pipeline/pipeline.rs b/src/pipeline/pipeline.rs index c1a7a3d..67285e8 100644 --- a/src/pipeline/pipeline.rs +++ b/src/pipeline/pipeline.rs @@ -135,8 +135,6 @@ 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 pipeline_start = std::time::Instant::now(); - let transform_start = std::time::Instant::now(); let transformed = self.run_transforms(input)?; let transform_elapsed = transform_start.elapsed(); @@ -147,7 +145,7 @@ impl Pipeline { let steps_elapsed = steps_start.elapsed(); debug!(duration_ms = steps_elapsed.as_millis(), "Step phase completed"); - let total_elapsed = pipeline_start.elapsed(); + let total_elapsed = transform_start.elapsed(); debug!(duration_ms = total_elapsed.as_millis(), "Pipeline execution completed"); Ok(result)