OXYGENHUB
# 5d79b5c2de88 oxygen / crates / oxy-core / src / timing.rs
3.7 KiB · Rust · last changed A Git import commit costs what it changes 1 month ago source blame history raw
1 
//! Opt-in phase timings (`OXY_TIMINGS=1`): each named phase prints its
2 
//! duration to stderr, for measuring where a command spends its time
3 
//! without a profiler. With the counting allocator installed (the `oxy`
4 
//! binary's `alloc-stats` feature), each also prints live and peak memory
5 
//! and what the phase allocated.
6
7 
use std::sync::OnceLock;
8 
use std::time::Instant;
9
10 
pub fn enabled() -> bool {
11 
    static ON: OnceLock<bool> = OnceLock::new();
12 
    *ON.get_or_init(|| std::env::var_os("OXY_TIMINGS").is_some_and(|v| !v.is_empty() && v != "0"))
13 
}
14
15 
/// Report a duration measured by hand (several intervals summed), if timings are on.
16 
pub fn record(name: &str, d: std::time::Duration) {
17 
    if enabled() {
18 
        eprintln!("timing {:<28} {:>9.2} ms", name, d.as_secs_f64() * 1000.0);
19 
    }
20 
}
21
22 
/// Prints `timing <name> <ms>` when dropped, if timings are on.
23 
pub struct Phase {
24 
    name: &'static str,
25 
    started: Option<Instant>,
26 
    /// Allocator counters at the start, when counting.
27 
    mem: Option<crate::alloc_stats::Stats>,
28 
}
29
30 
/// Start timing a phase; the guard reports when it goes out of scope.
31 
pub fn phase(name: &'static str) -> Phase {
32 
    let on = enabled();
33 
    Phase {
34 
        name,
35 
        started: on.then(Instant::now),
36 
        mem: if on {
37 
            crate::alloc_stats::stats()
38 
        } else {
39 
            None
40 
        },
41 
    }
42 
}
43
44 
fn mib(n: usize) -> f64 {
45 
    n as f64 / (1024.0 * 1024.0)
46 
}
47
48 
/// The allocator's counters as one line, when counting: for the end of a
49 
/// command.
50 
pub fn memory_summary() {
51 
    if let (true, Some(s)) = (enabled(), crate::alloc_stats::stats()) {
52 
        eprintln!(
53 
            "memory peak {:.1} MiB, live {:.1} MiB, {:.1} MiB in {} allocations",
54 
            mib(s.peak),
55 
            mib(s.live),
56 
            mib(s.total),
57 
            s.count
58 
        );
59 
    }
60 
}
61
62 
impl Drop for Phase {
63 
    fn drop(&mut self) {
64 
        if let Some(t) = self.started {
65 
            let ms = t.elapsed().as_secs_f64() * 1000.0;
66 
            match (self.mem, crate::alloc_stats::stats()) {
67 
                (Some(a), Some(b)) => eprintln!(
68 
                    "timing {:<28} {:>9.2} ms  live {:>8.1} MiB  peak {:>8.1} MiB  +{:.1} MiB in {} allocs",
69 
                    self.name,
70 
                    ms,
71 
                    mib(b.live),
72 
                    mib(b.peak),
73 
                    mib(b.total - a.total),
74 
                    b.count - a.count
75 
                ),
76 
                _ => eprintln!("timing {:<28} {:>9.2} ms", self.name, ms),
77 
            }
78 
        }
79 
    }
80 
}
81
82 
static TOTALS: std::sync::Mutex<Vec<(&'static str, std::time::Duration)>> =
83 
    std::sync::Mutex::new(Vec::new());
84
85 
/// Add `d` to the running total for `name`, for a phase repeated many
86 
/// times (once per imported commit, say); `report_totals` prints them.
87 
pub fn add(name: &'static str, d: std::time::Duration) {
88 
    if !enabled() {
89 
        return;
90 
    }
91 
    let mut t = TOTALS.lock().unwrap_or_else(|e| e.into_inner());
92 
    match t.iter_mut().find(|(n, _)| *n == name) {
93 
        Some((_, total)) => *total += d,
94 
        None => t.push((name, d)),
95 
    }
96 
}
97
98 
/// Print and clear the totals `add` gathered.
99 
pub fn report_totals() {
100 
    if !enabled() {
101 
        return;
102 
    }
103 
    let t = std::mem::take(&mut *TOTALS.lock().unwrap_or_else(|e| e.into_inner()));
104 
    for (name, d) in t {
105 
        record(name, d);
106 
    }
107 
}
108
109 
/// Times from one point to the next, adding each interval to a total.
110 
pub struct Laps(Option<Instant>);
111
112 
impl Laps {
113 
    pub fn start() -> Laps {
114 
        Laps(enabled().then(Instant::now))
115 
    }
116 
    /// Add the time since the last lap to `name`'s total.
117 
    pub fn lap(&mut self, name: &'static str) {
118 
        if let Some(t) = &mut self.0 {
119 
            let now = Instant::now();
120 
            add(name, now - *t);
121 
            *t = now;
122 
        }
123 
    }
124 
}