gqls/
profile.rs

1//! Phase timing for `--profile`.
2//!
3//! Off by default and built to cost nothing when off: a span is created around
4//! each phase, but with profiling disabled it holds no clock reading, takes no
5//! lock, allocates nothing, and its `Drop` returns immediately. The only work
6//! left on the hot path is one relaxed atomic load per phase.
7//!
8//! Phases are a flat list — names carry their own structure
9//! (`semantic: model load`) rather than a nesting scheme, because the report is
10//! read top to bottom and the total is wall time, not a sum.
11
12use std::sync::atomic::{AtomicBool, Ordering};
13use std::sync::Mutex;
14use std::time::{Duration, Instant};
15
16static ENABLED: AtomicBool = AtomicBool::new(false);
17static PHASES: Mutex<Vec<Phase>> = Mutex::new(Vec::new());
18
19/// One measured phase.
20pub struct Phase {
21    pub name: &'static str,
22    pub elapsed: Duration,
23    /// What the phase did — record counts, bytes, a cache verdict.
24    pub note: Option<String>,
25}
26
27/// Turn profiling on. Called once from the CLI when `--profile` is passed.
28pub fn enable() {
29    ENABLED.store(true, Ordering::Relaxed);
30}
31
32pub fn enabled() -> bool {
33    ENABLED.load(Ordering::Relaxed)
34}
35
36/// Start timing a phase. The returned span records it when dropped; with
37/// profiling off it is inert.
38pub fn span(name: &'static str) -> Span {
39    Span {
40        name,
41        // No clock read at all when disabled — this is the whole point.
42        start: enabled().then(Instant::now),
43        note: None,
44    }
45}
46
47pub struct Span {
48    name: &'static str,
49    start: Option<Instant>,
50    note: Option<String>,
51}
52
53impl Span {
54    /// Attach detail to this phase. The closure runs only when profiling is on,
55    /// so formatting a note never costs anything in a normal run.
56    pub fn note(&mut self, f: impl FnOnce() -> String) {
57        if self.start.is_some() {
58            self.note = Some(f());
59        }
60    }
61}
62
63impl Drop for Span {
64    fn drop(&mut self) {
65        let Some(start) = self.start else { return };
66        if let Ok(mut phases) = PHASES.lock() {
67            phases.push(Phase {
68                name: self.name,
69                elapsed: start.elapsed(),
70                note: self.note.take(),
71            });
72        }
73    }
74}
75
76/// Every phase recorded so far, in the order they finished.
77pub fn phases() -> Vec<Phase> {
78    PHASES
79        .lock()
80        .map(|mut p| std::mem::take(&mut *p))
81        .unwrap_or_default()
82}
83
84/// The report, as lines ready for stderr. Empty when nothing was measured.
85pub fn report(total: Duration) -> Vec<String> {
86    let phases = phases();
87    if phases.is_empty() {
88        return Vec::new();
89    }
90    let width = phases
91        .iter()
92        .map(|p| p.name.len())
93        .max()
94        .unwrap_or(0)
95        .max(5);
96    let mut out: Vec<String> = phases
97        .iter()
98        .map(|p| {
99            let note = p.note.as_deref().unwrap_or_default();
100            format!(
101                "  {:<width$}  {:>8}  {note}",
102                p.name,
103                ms(p.elapsed),
104                width = width
105            )
106            .trim_end()
107            .to_string()
108        })
109        .collect();
110    out.push(format!(
111        "  {:<width$}  {:>8}",
112        "─".repeat(width.min(20)),
113        "",
114        width = width
115    ));
116    out.push(format!(
117        "  {:<width$}  {:>8}",
118        "total",
119        ms(total),
120        width = width
121    ));
122    out
123}
124
125/// Phases as JSON, for storing a baseline and diffing runs.
126pub fn json(total: Duration) -> serde_json::Value {
127    let phases = phases();
128    serde_json::json!({
129        "total_ms": total.as_secs_f64() * 1000.0,
130        "phases": phases
131            .iter()
132            .map(|p| serde_json::json!({
133                "name": p.name,
134                "ms": p.elapsed.as_secs_f64() * 1000.0,
135                "note": p.note,
136            }))
137            .collect::<Vec<_>>(),
138    })
139}
140
141fn ms(d: Duration) -> String {
142    format!("{:.1}ms", d.as_secs_f64() * 1000.0)
143}
144
145#[cfg(test)]
146mod tests {
147    use super::*;
148
149    #[test]
150    fn a_span_is_inert_when_profiling_is_off() {
151        // the default; nothing is recorded and no clock is read
152        let mut s = span("off");
153        s.note(|| panic!("the note closure must not run when disabled"));
154        drop(s);
155        assert!(phases().is_empty());
156    }
157
158    #[test]
159    fn an_enabled_span_records_its_name_and_note() {
160        enable();
161        {
162            let mut s = span("on");
163            s.note(|| "42 records".to_string());
164        }
165        let recorded = phases();
166        assert_eq!(recorded.len(), 1);
167        assert_eq!(recorded[0].name, "on");
168        assert_eq!(recorded[0].note.as_deref(), Some("42 records"));
169        // phases() drains, so a second call sees nothing
170        assert!(phases().is_empty());
171        ENABLED.store(false, Ordering::Relaxed);
172    }
173}
gqls/profile.rs

gqls/
profile.rs
