renacer_core/
phase_timer.rs

1//! PMAT-284: Lightweight sub-phase timing for CPU-GPU pipelining analysis
2//!
3//! `PhaseTimer` captures named sub-phases within a hot loop with minimal
4//! overhead when disabled. Designed for iteration-scheduler-level instrumentation
5//! where BrickProfiler (GPU-side) and InferenceTracer (model-level) don't apply.
6//!
7//! # Usage
8//!
9//! ```ignore
10//! let mut timer = PhaseTimer::from_env("PMAT_283_TIMING");
11//!
12//! loop {
13//!     timer.start();
14//!     timer.mark("lock");      // write lock acquired
15//!     // ... scheduling ...
16//!     timer.mark("sched");     // scheduling done
17//!     // ... decode step ...
18//!     timer.mark("decode");    // GPU decode done
19//!     // ... token distribution ...
20//!     timer.mark("dist");      // tokens distributed
21//!     timer.emit(iteration, batch_size);  // prints if enabled + interval
22//! }
23//! ```
24//!
25//! Output: `[PMAT-283] iter=42, m=4: lock=3µs sched=12µs decode=7412µs dist=84µs total=7511µs`
26
27use std::time::Instant;
28
29/// Lightweight sub-phase timer for hot-path instrumentation.
30///
31/// Zero overhead when disabled (all methods are no-ops).
32/// When enabled, captures phase boundaries via `mark()` and
33/// emits structured timing via `emit()`.
34pub struct PhaseTimer {
35    enabled: bool,
36    start: Option<Instant>,
37    marks: Vec<(&'static str, Instant)>,
38    label: &'static str,
39    /// Emit every N iterations (0 = first 5 then every 100)
40    emit_interval: u64,
41}
42
43impl PhaseTimer {
44    /// Create a timer controlled by an environment variable.
45    ///
46    /// Returns a disabled (zero-cost) timer if the env var is unset or != "1".
47    pub fn from_env(env_var: &'static str, label: &'static str) -> Self {
48        let enabled = std::env::var(env_var).map(|v| v == "1").unwrap_or(false);
49        Self {
50            enabled,
51            start: None,
52            marks: Vec::with_capacity(if enabled { 8 } else { 0 }),
53            label,
54            emit_interval: 0,
55        }
56    }
57
58    /// Create an always-enabled timer (for testing).
59    #[cfg(test)]
60    pub fn enabled(label: &'static str) -> Self {
61        Self {
62            enabled: true,
63            start: None,
64            marks: Vec::with_capacity(8),
65            label,
66            emit_interval: 0,
67        }
68    }
69
70    /// Start a new timing cycle. Call at the top of each iteration.
71    #[inline]
72    pub fn start(&mut self) {
73        if self.enabled {
74            self.marks.clear();
75            self.start = Some(Instant::now());
76        }
77    }
78
79    /// Mark the end of a named phase. The duration is from the previous
80    /// mark (or start) to now.
81    #[inline]
82    pub fn mark(&mut self, phase: &'static str) {
83        if self.enabled {
84            self.marks.push((phase, Instant::now()));
85        }
86    }
87
88    /// Emit timing data if enabled and the iteration matches the emit interval.
89    ///
90    /// Default interval: first 5 iterations, then every 100.
91    pub fn emit(&self, iteration: u64, batch_size: usize) {
92        if !self.enabled {
93            return;
94        }
95        // Default: first 5, then every 100
96        let should_emit = if self.emit_interval == 0 {
97            iteration <= 5 || iteration % 100 == 0
98        } else {
99            iteration % self.emit_interval == 0
100        };
101        if !should_emit {
102            return;
103        }
104
105        let Some(start) = self.start else { return };
106        let mut parts = Vec::with_capacity(self.marks.len());
107        let mut prev = start;
108        for (name, ts) in &self.marks {
109            let dur_us = ts.duration_since(prev).as_micros();
110            parts.push(format!("{name}={dur_us}µs"));
111            prev = *ts;
112        }
113        let total_us = prev.duration_since(start).as_micros();
114        eprintln!(
115            "[{}] iter={}, m={}: {} total={}µs",
116            self.label,
117            iteration,
118            batch_size,
119            parts.join(" "),
120            total_us,
121        );
122    }
123
124    /// Check if the timer is enabled.
125    #[inline]
126    #[must_use]
127    pub fn is_enabled(&self) -> bool {
128        self.enabled
129    }
130}
131
132#[cfg(test)]
133mod tests {
134    use super::*;
135
136    #[test]
137    fn test_disabled_is_noop() {
138        let mut t = PhaseTimer::from_env("NONEXISTENT_ENV_VAR_12345", "test");
139        assert!(!t.is_enabled());
140        t.start();
141        t.mark("a");
142        t.mark("b");
143        t.emit(1, 4); // should not panic or print
144    }
145
146    #[test]
147    fn test_enabled_captures_phases() {
148        let mut t = PhaseTimer::enabled("test");
149        t.start();
150        std::thread::sleep(std::time::Duration::from_micros(100));
151        t.mark("phase_a");
152        std::thread::sleep(std::time::Duration::from_micros(100));
153        t.mark("phase_b");
154        assert_eq!(t.marks.len(), 2);
155        assert_eq!(t.marks[0].0, "phase_a");
156        assert_eq!(t.marks[1].0, "phase_b");
157    }
158}
renacer_core/phase_timer.rs

renacer_core/
phase_timer.rs
