refactor: add timed! macro and TimedStep for timing infrastructure

Replace manual Instant::now()/elapsed()/println!() boilerplate with two
primitives: timed! for hot-path Duration accumulation (pipeline.rs) and
TimedStep for progressive CLI output with auto dot-padding and tracing
spans (main.rs, processing.rs, cv.rs). Duration display uses {:?} for
automatic unit selection everywhere.

Author: jspaezp

rust/timsseek/src/ml/cv.rs

@@ -1,4 +1,5 @@
 pub use super::TargetDecoy;
+use crate::scoring::timings::TimedStep;
 pub use forust_ml::constraints::{
     Constraint,
     ConstraintMap,
@@ -403,9 +404,9 @@ impl<T: FeatureLike> CrossValidatedScorer<T> {
         self.fold_classifiers.clear();
         (0..self.n_folds).for_each(|_| self.fold_classifiers.push(None));
         for fold in 0..self.n_folds {
-            let start = std::time::Instant::now();
+            let step = TimedStep::begin_stderr(format_args!("  Training fold {}/{}...", fold + 1, self.n_folds));
             self.fit_fold(fold, train_buffer, val_buffer)?;
-            eprintln!("  Training fold {}/{} ... {:?}", fold + 1, self.n_folds, start.elapsed());
+            step.finish();
         }
 
         Ok(())
@@ -415,7 +416,7 @@ impl<T: FeatureLike> CrossValidatedScorer<T> {
         let mut scores = vec![0.0; self.data.len()];
         let mut buffer = DataBuffer::default();
 
-        let score_start = std::time::Instant::now();
+        let step = TimedStep::begin_stderr("  Scoring folds...");
         for train_i in 0..self.n_folds {
             let early_stop_i = self.next_fold(train_i);
 
@@ -440,7 +441,7 @@ impl<T: FeatureLike> CrossValidatedScorer<T> {
                 }
             }
         }
-        eprintln!("  Scoring folds ... {:?}", score_start.elapsed());
+        step.finish();
 
         let div_factor = (self.n_folds - 2) as f64;
         scores.iter_mut().for_each(|x| {

rust/timsseek/src/scoring/pipeline.rs

@@ -28,7 +28,7 @@ use crate::{
 };
 #[cfg(feature = "rayon")]
 use rayon::prelude::*;
-use std::time::Instant;
+use crate::timed;
 use timscentroid::rt_mapping::{
     MS1CycleIndex,
     RTIndex,
@@ -599,15 +599,14 @@ impl<I: ScorerQueriable> Scorer<I> {
         buffer: &mut TraceScorer,
         timings: &mut ScoreTimings,
     ) -> Option<ScoredCandidate> {
-        let st = Instant::now();
-        let (metadata, scoring_ctx) =
+        let (metadata, scoring_ctx) = timed!(timings.extraction,
             tracing::span!(tracing::Level::TRACE, "score_calibrated::extraction").in_scope(
                 || match self.build_calibrated_extraction(item, calibration) {
                     Ok(result) => Some(result),
                     Err(_) => None,
                 },
-            )?;
-        timings.extraction += st.elapsed();
+            )
+        )?;
 
         if scoring_ctx
             .expected_intensities
@@ -617,39 +616,37 @@ impl<I: ScorerQueriable> Scorer<I> {
             return None;
         }
 
-        let st = Instant::now();
-        let apex_score =
+        let apex_score = timed!(timings.scoring,
             tracing::span!(tracing::Level::TRACE, "score_calibrated::apex_scoring").in_scope(
                 || {
                     buffer
                         .find_apex(&scoring_ctx, &|idx| self.map_rt_index_to_milis(idx))
                         .ok()
                 },
-            )?;
-        timings.scoring += st.elapsed();
+            )
+        )?;
 
-        let st = Instant::now();
-        let spectral_tol = calibration.get_spectral_tolerance();
-        let isotope_tol = calibration.get_isotope_tolerance();
-        let (inner_collector, isotope_collector) =
+        let (inner_collector, isotope_collector) = timed!(timings.spectral_query, {
+            let spectral_tol = calibration.get_spectral_tolerance();
+            let isotope_tol = calibration.get_isotope_tolerance();
             tracing::span!(tracing::Level::TRACE, "score_calibrated::secondary_query")
-                .in_scope(|| self.execute_secondary_query(item, &apex_score, &spectral_tol, &isotope_tol));
-        timings.spectral_query += st.elapsed();
+                .in_scope(|| self.execute_secondary_query(item, &apex_score, &spectral_tol, &isotope_tol))
+        });
 
         let nqueries = scoring_ctx.chromatograms.fragments.num_ions() as u8;
-        let st = Instant::now();
-        let out = tracing::span!(tracing::Level::TRACE, "score_calibrated::finalize").in_scope(
-            || {
-                self.finalize_results(
-                    &metadata,
-                    nqueries,
-                    &apex_score,
-                    &inner_collector,
-                    &isotope_collector,
-                )
-            },
+        let out = timed!(timings.assembly,
+            tracing::span!(tracing::Level::TRACE, "score_calibrated::finalize").in_scope(
+                || {
+                    self.finalize_results(
+                        &metadata,
+                        nqueries,
+                        &apex_score,
+                        &inner_collector,
+                        &isotope_collector,
+                    )
+                },
+            )
         );
-        timings.assembly += st.elapsed();
 
         match out {
             Ok(res) => Some(res),
@@ -722,21 +719,20 @@ impl<I: ScorerQueriable> Scorer<I> {
         buffer: &mut TraceScorer,
         timings: &mut super::timings::PrescoreTimings,
     ) -> Option<ApexLocation> {
-        let st = Instant::now();
-        let scoring_ctx = tracing::span!(tracing::Level::TRACE, "prescore::extraction")
-            .in_scope(|| {
-                super::extraction::build_extraction(
-                    &item.query,
-                    item.expected_intensity.clone(),
-                    &self.index,
-                    &self.broad_tolerance,
-                    Some(TOP_N_FRAGMENTS),
-                )
-                .ok()
-            });
-        timings.extraction += st.elapsed();
+        let scoring_ctx = timed!(timings.extraction,
+            tracing::span!(tracing::Level::TRACE, "prescore::extraction")
+                .in_scope(|| {
+                    super::extraction::build_extraction(
+                        &item.query,
+                        item.expected_intensity.clone(),
+                        &self.index,
+                        &self.broad_tolerance,
+                        Some(TOP_N_FRAGMENTS),
+                    )
+                    .ok()
+                })
+        )?;
 
-        let scoring_ctx = scoring_ctx?;
         if scoring_ctx
             .expected_intensities
             .fragment_intensities
@@ -745,13 +741,13 @@ impl<I: ScorerQueriable> Scorer<I> {
             return None;
         }
 
-        let st = Instant::now();
-        let result = tracing::span!(tracing::Level::TRACE, "prescore::scoring").in_scope(|| {
-            buffer
-                .find_apex_location(&scoring_ctx, &|idx| self.map_rt_index_to_milis(idx))
-                .ok()
-        });
-        timings.scoring += st.elapsed();
+        let result = timed!(timings.scoring,
+            tracing::span!(tracing::Level::TRACE, "prescore::scoring").in_scope(|| {
+                buffer
+                    .find_apex_location(&scoring_ctx, &|idx| self.map_rt_index_to_milis(idx))
+                    .ok()
+            })
+        );
 
         if result.is_some() {
             timings.n_scored += 1;

rust/timsseek/src/scoring/timings.rs

@@ -3,9 +3,98 @@
 //! This module provides timing measurement for each stage of the scoring process.
 //! The timings are aggregated across parallel scoring operations to provide overall
 //! performance metrics.
+//!
+//! Two helpers reduce timing boilerplate:
+//!
+//! - [`timed!`] — times a block and accumulates elapsed into a `Duration` field.
+//! - [`TimedStep`] — progressive CLI output: prints a label immediately, then
+//!   appends elapsed time when the work finishes.
 
 use serde::Serialize;
-use std::time::Duration;
+use std::fmt;
+use std::time::{Duration, Instant};
+
+/// Time a block, accumulate elapsed into `$target`, return the block's value.
+///
+/// ```ignore
+/// let ctx = timed!(timings.extraction, {
+///     build_extraction(&query, &index, &tolerance)
+/// })?;
+/// ```
+#[doc(hidden)]
+#[macro_export]
+macro_rules! timed {
+    ($target:expr, $body:expr) => {{
+        let __start = std::time::Instant::now();
+        let __result = $body;
+        $target += __start.elapsed();
+        __result
+    }};
+}
+
+/// A timed step that prints a dot-padded label immediately, opens a tracing
+/// span, and appends elapsed time on finish.
+///
+/// ```ignore
+/// let step = TimedStep::begin("Loading speclib");
+/// let speclib = load_speclib()?;
+/// let elapsed = step.finish_with(format_args!("{} entries", speclib.len()));
+/// // terminal: "Loading speclib .......... 834.567ms (225178 entries)"
+/// ```
+pub struct TimedStep {
+    start: Instant,
+    stderr: bool,
+    _span: tracing::span::EnteredSpan,
+}
+
+/// Column width for dot-padded labels on stdout.
+const LABEL_WIDTH: usize = 26;
+
+impl TimedStep {
+    /// Dot-pad `label` to stdout, open a tracing span, flush, start clock.
+    pub fn begin(label: impl fmt::Display) -> Self {
+        let label = label.to_string();
+        let span = tracing::info_span!("step", label = label.as_str());
+        let dots = LABEL_WIDTH.saturating_sub(label.len() + 1);
+        if dots > 0 {
+            print!("{label} {:.<width$}", "", width = dots);
+        } else {
+            print!("{label}");
+        }
+        std::io::Write::flush(&mut std::io::stdout()).ok();
+        Self { start: Instant::now(), stderr: false, _span: span.entered() }
+    }
+
+    /// Print `label` to stderr (no dot-padding), open a tracing span, start clock.
+    pub fn begin_stderr(label: impl fmt::Display) -> Self {
+        let label = label.to_string();
+        let span = tracing::info_span!("step", label = label.as_str());
+        eprint!("{label}");
+        Self { start: Instant::now(), stderr: true, _span: span.entered() }
+    }
+
+    /// Print ` {elapsed:?}\n`, return Duration.
+    pub fn finish(self) -> Duration {
+        let d = self.start.elapsed();
+        self.emit(format_args!(" {:?}", d));
+        d
+    }
+
+    /// Print ` {elapsed:?} ({detail})\n`, return Duration.
+    pub fn finish_with(self, detail: impl fmt::Display) -> Duration {
+        let d = self.start.elapsed();
+        self.emit(format_args!(" {:?} ({})", d, detail));
+        d
+    }
+
+    fn emit(&self, msg: fmt::Arguments<'_>) {
+        if self.stderr {
+            eprintln!("{msg}");
+        } else {
+            println!("{msg}");
+        }
+    }
+}
 
 /// Accumulated timing measurements for the four scoring stages.
 ///

rust/timsseek_cli/src/main.rs

@@ -8,6 +8,7 @@ use timsquery::TimsTofPath;
 use timsquery::serde::load_index_auto;
 use timsquery::utils::TupleRange;
 use timsseek::scoring::Scorer;
+use timsseek::scoring::timings::TimedStep;
 use tracing::{
     error,
     info,
@@ -252,7 +253,7 @@ fn process_single_file(
             path: Some(dotd_file.to_string_lossy().to_string()),
         })?;
 
-    let index_start = std::time::Instant::now();
+    let step = TimedStep::begin("Loading index");
     let index = load_index_auto(
         dotd_file.to_str().ok_or_else(|| errors::CliError::Io {
             source: "Invalid path encoding".to_string(),
@@ -261,8 +262,7 @@ fn process_single_file(
         None,
     )?
     .into_eager()?;
-    let load_index_ms = index_start.elapsed().as_millis() as u64;
-    println!("Loading index ........... {:.1}s", load_index_ms as f64 / 1000.0);
+    let load_index_ms = step.finish().as_millis() as u64;
 
     let fragmented_range = get_frag_range(&timstofpath)?;
 
@@ -505,31 +505,29 @@ fn main() -> std::result::Result<(), errors::CliError> {
     let mut successful_files: Vec<std::path::PathBuf> = Vec::new();
 
     // Load speclib once (shared across all files)
-    let speclib_start = std::time::Instant::now();
+    let step = TimedStep::begin("Loading speclib");
     info!("Building database from speclib file {:?}", validated.speclib_path);
     info!("Decoy generation strategy: {}", config.analysis.decoy_strategy);
     let speclib = timsseek::data_sources::speclib::Speclib::from_file(
         &validated.speclib_path,
         config.analysis.decoy_strategy,
     ).map_err(|e| errors::CliError::Config { source: format!("Failed to load speclib: {:?}", e) })?;
-    let load_speclib_ms = speclib_start.elapsed().as_millis() as u64;
-    println!("Loading speclib ......... {:.1}s ({} entries)", load_speclib_ms as f64 / 1000.0, speclib.len());
+    let load_speclib_ms = step.finish_with(format_args!("{} entries", speclib.len())).as_millis() as u64;
 
     // Load calibration library once (if provided)
-    let calib_start = std::time::Instant::now();
-    let calib_lib = match &validated.calib_lib_path {
+    let (calib_lib, load_calib_lib_ms) = match &validated.calib_lib_path {
         Some(p) => {
+            let step = TimedStep::begin("Loading calib lib");
             info!("Loading calibration library from {:?}", p);
             let lib = timsseek::data_sources::speclib::Speclib::from_file(
                 p,
                 config.analysis.decoy_strategy,
             ).map_err(|e| errors::CliError::Config { source: format!("Failed to load calib lib: {:?}", e) })?;
-            println!("Loading calib lib ....... {:.1}s ({} entries)", calib_start.elapsed().as_secs_f64(), lib.len());
-            Some(lib)
+            let ms = step.finish_with(format_args!("{} entries", lib.len())).as_millis() as u64;
+            (Some(lib), ms)
         }
-        None => None,
+        None => (None, 0),
     };
-    let load_calib_lib_ms = calib_start.elapsed().as_millis() as u64;
 
     run_report.load_speclib_ms = load_speclib_ms;
     run_report.load_calib_lib_ms = load_calib_lib_ms;