ite_cli/
profile.rs

1//! Lightweight span profiler, compiled in only under the `profile` cargo
2//! feature (what `cargo profile-tui` builds with). Shipped builds contain
3//! zero instrumentation: without the feature, `span()` returns a unit
4//! struct with no `Drop`, which the optimizer erases entirely. When
5//! compiled in, recording is enabled by `ITE_PROFILE=<output-path>` and the
6//! dump is a plain-text table. `Stats` and `format_duration` stay
7//! unconditional — the profile driver uses them for its own latency report.
8
9use std::time::Duration;
10
11#[cfg(feature = "profile")]
12mod recording {
13    use std::path::Path;
14    use std::sync::{Mutex, OnceLock};
15    use std::time::{Duration, Instant};
16
17    use super::{Stats, format_duration};
18
19    /// Collects labeled durations and renders a summary table.
20    pub struct Registry {
21        records: Mutex<Vec<(&'static str, Duration)>>,
22    }
23
24    impl Registry {
25        pub const fn new() -> Self {
26            Self {
27                records: Mutex::new(Vec::new()),
28            }
29        }
30
31        pub fn record(&self, label: &'static str, duration: Duration) {
32            self.records.lock().unwrap().push((label, duration));
33        }
34
35        /// A table of per-label stats, ordered by total time descending.
36        pub fn summary(&self) -> String {
37            let records = self.records.lock().unwrap();
38            if records.is_empty() {
39                return "(no spans recorded)\n".to_string();
40            }
41            let mut by_label: Vec<(&'static str, Vec<Duration>)> = Vec::new();
42            for &(label, duration) in records.iter() {
43                match by_label.iter_mut().find(|(l, _)| *l == label) {
44                    Some((_, durations)) => durations.push(duration),
45                    None => by_label.push((label, vec![duration])),
46                }
47            }
48            let mut rows: Vec<(&'static str, Stats)> = by_label
49                .into_iter()
50                .map(|(label, durations)| (label, Stats::from_durations(&durations).unwrap()))
51                .collect();
52            rows.sort_by_key(|(_, s)| std::cmp::Reverse(s.total));
53
54            let mut out = format!(
55                "{:<24} {:>7} {:>9} {:>9} {:>9} {:>9} {:>9}\n",
56                "span", "count", "total", "mean", "p50", "p95", "max"
57            );
58            for (label, s) in rows {
59                out.push_str(&format!(
60                    "{:<24} {:>7} {:>9} {:>9} {:>9} {:>9} {:>9}\n",
61                    label,
62                    s.count,
63                    format_duration(s.total),
64                    format_duration(s.mean),
65                    format_duration(s.p50),
66                    format_duration(s.p95),
67                    format_duration(s.max),
68                ));
69            }
70            out
71        }
72
73        pub fn write_to(&self, path: &Path) -> std::io::Result<()> {
74            std::fs::write(path, self.summary())
75        }
76    }
77
78    impl Default for Registry {
79        fn default() -> Self {
80            Self::new()
81        }
82    }
83
84    pub static GLOBAL: Registry = Registry::new();
85
86    /// The output path from `ITE_PROFILE`, if profiling is enabled.
87    pub fn output_path() -> Option<&'static str> {
88        static PATH: OnceLock<Option<String>> = OnceLock::new();
89        PATH.get_or_init(|| std::env::var("ITE_PROFILE").ok().filter(|p| !p.is_empty()))
90            .as_deref()
91    }
92
93    pub fn enabled() -> bool {
94        output_path().is_some()
95    }
96
97    /// Times a scope and records it in [`GLOBAL`] on drop (no-op when
98    /// `ITE_PROFILE` is unset).
99    pub struct Span {
100        label: &'static str,
101        start: Option<Instant>,
102    }
103
104    #[must_use]
105    pub fn span(label: &'static str) -> Span {
106        Span {
107            label,
108            start: enabled().then(Instant::now),
109        }
110    }
111
112    impl Drop for Span {
113        fn drop(&mut self) {
114            if let Some(start) = self.start {
115                GLOBAL.record(self.label, start.elapsed());
116            }
117        }
118    }
119}
120
121#[cfg(feature = "profile")]
122pub use recording::*;
123
124#[cfg(not(feature = "profile"))]
125mod noop {
126    /// Zero-cost stand-in: a unit struct with no `Drop`, so `span()` calls
127    /// vanish under optimization. `#[inline(always)]` matters — the binary
128    /// crate calls this across the crate boundary, where a non-generic
129    /// function would otherwise survive without LTO.
130    pub struct Span;
131
132    #[must_use]
133    #[inline(always)]
134    pub fn span(_label: &'static str) -> Span {
135        Span
136    }
137}
138
139#[cfg(not(feature = "profile"))]
140pub use noop::*;
141
142/// Summary statistics over a set of durations.
143#[derive(Clone, Copy, Debug, PartialEq, Eq)]
144pub struct Stats {
145    pub count: usize,
146    pub total: Duration,
147    pub mean: Duration,
148    pub p50: Duration,
149    pub p95: Duration,
150    pub max: Duration,
151}
152
153impl Stats {
154    /// `None` when `durations` is empty.
155    pub fn from_durations(durations: &[Duration]) -> Option<Self> {
156        if durations.is_empty() {
157            return None;
158        }
159        let mut sorted = durations.to_vec();
160        sorted.sort();
161        let percentile = |q: f64| {
162            let index = ((sorted.len() - 1) as f64 * q).round() as usize;
163            sorted[index]
164        };
165        let total: Duration = sorted.iter().sum();
166        Some(Self {
167            count: sorted.len(),
168            total,
169            mean: total / sorted.len() as u32,
170            p50: percentile(0.50),
171            p95: percentile(0.95),
172            max: *sorted.last().unwrap(),
173        })
174    }
175}
176
177/// Adaptive human-readable duration: ns, µs, ms, or s.
178pub fn format_duration(d: Duration) -> String {
179    let nanos = d.as_nanos();
180    if nanos < 1_000 {
181        format!("{nanos}ns")
182    } else if nanos < 1_000_000 {
183        format!("{:.1}µs", nanos as f64 / 1_000.0)
184    } else if nanos < 1_000_000_000 {
185        format!("{:.2}ms", nanos as f64 / 1_000_000.0)
186    } else {
187        format!("{:.2}s", nanos as f64 / 1_000_000_000.0)
188    }
189}
190
191#[cfg(test)]
192mod tests {
193    use super::*;
194
195    fn ms(n: u64) -> Duration {
196        Duration::from_millis(n)
197    }
198
199    #[test]
200    fn stats_of_known_durations() {
201        let durations: Vec<Duration> = (1..=10).map(ms).collect();
202        let stats = Stats::from_durations(&durations).unwrap();
203        assert_eq!(stats.count, 10);
204        assert_eq!(stats.total, ms(55));
205        assert_eq!(stats.mean, Duration::from_micros(5500));
206        assert_eq!(stats.max, ms(10));
207        // Percentile index = round((n-1) * q) over the sorted set.
208        assert_eq!(stats.p50, ms(6));
209        assert_eq!(stats.p95, ms(10));
210    }
211
212    #[test]
213    fn stats_of_single_duration() {
214        let stats = Stats::from_durations(&[ms(10)]).unwrap();
215        assert_eq!(stats.count, 1);
216        assert_eq!(stats.mean, ms(10));
217        assert_eq!(stats.p50, ms(10));
218        assert_eq!(stats.p95, ms(10));
219        assert_eq!(stats.max, ms(10));
220    }
221
222    #[test]
223    fn stats_of_nothing_is_none() {
224        assert_eq!(Stats::from_durations(&[]), None);
225    }
226
227    #[test]
228    fn stats_do_not_require_sorted_input() {
229        let stats = Stats::from_durations(&[ms(9), ms(1), ms(5)]).unwrap();
230        assert_eq!(stats.p50, ms(5));
231        assert_eq!(stats.max, ms(9));
232    }
233
234    #[test]
235    fn durations_format_adaptively() {
236        assert_eq!(format_duration(Duration::from_nanos(250)), "250ns");
237        assert_eq!(format_duration(Duration::from_nanos(12_500)), "12.5µs");
238        assert_eq!(format_duration(Duration::from_micros(3_400)), "3.40ms");
239        assert_eq!(format_duration(Duration::from_millis(2_500)), "2.50s");
240    }
241}
242
243#[cfg(all(test, feature = "profile"))]
244mod registry_tests {
245    use super::*;
246    use std::time::Duration;
247
248    fn ms(n: u64) -> Duration {
249        Duration::from_millis(n)
250    }
251
252    #[test]
253    fn summary_orders_labels_by_total_descending() {
254        let reg = Registry::new();
255        reg.record("cheap", ms(2));
256        reg.record("expensive", ms(50));
257        reg.record("cheap", ms(3));
258        let summary = reg.summary();
259        let expensive_at = summary.find("expensive").unwrap();
260        let cheap_at = summary.find("cheap").unwrap();
261        assert!(expensive_at < cheap_at, "summary:\n{summary}");
262        assert!(summary.contains("count"), "has a header:\n{summary}");
263    }
264
265    #[test]
266    fn summary_reports_counts() {
267        let reg = Registry::new();
268        reg.record("draw", ms(1));
269        reg.record("draw", ms(1));
270        reg.record("draw", ms(1));
271        assert!(reg.summary().contains('3'));
272    }
273
274    #[test]
275    fn empty_summary_says_so() {
276        assert_eq!(Registry::new().summary(), "(no spans recorded)\n");
277    }
278
279    #[test]
280    fn write_to_writes_the_summary() {
281        let dir = tempfile::tempdir().unwrap();
282        let path = dir.path().join("profile.txt");
283        let reg = Registry::new();
284        reg.record("scan", ms(7));
285        reg.write_to(&path).unwrap();
286        assert_eq!(std::fs::read_to_string(&path).unwrap(), reg.summary());
287    }
288}
ite_cli/profile.rs

ite_cli/
profile.rs
