//! Opt-in phase timings (`OXY_TIMINGS=1`): each named phase prints its //! duration to stderr, for measuring where a command spends its time //! without a profiler. With the counting allocator installed (the `oxy` //! binary's `alloc-stats` feature), each also prints live and peak memory //! and what the phase allocated. use std::sync::OnceLock; use std::time::Instant; pub fn enabled() -> bool { static ON: OnceLock = OnceLock::new(); *ON.get_or_init(|| std::env::var_os("OXY_TIMINGS").is_some_and(|v| !v.is_empty() && v != "0")) } /// Report a duration measured by hand (several intervals summed), if timings are on. pub fn record(name: &str, d: std::time::Duration) { if enabled() { eprintln!("timing {:<28} {:>9.2} ms", name, d.as_secs_f64() * 1000.0); } } /// Prints `timing ` when dropped, if timings are on. pub struct Phase { name: &'static str, started: Option, /// Allocator counters at the start, when counting. mem: Option, } /// Start timing a phase; the guard reports when it goes out of scope. pub fn phase(name: &'static str) -> Phase { let on = enabled(); Phase { name, started: on.then(Instant::now), mem: if on { crate::alloc_stats::stats() } else { None }, } } fn mib(n: usize) -> f64 { n as f64 / (1024.0 * 1024.0) } /// The allocator's counters as one line, when counting: for the end of a /// command. pub fn memory_summary() { if let (true, Some(s)) = (enabled(), crate::alloc_stats::stats()) { eprintln!( "memory peak {:.1} MiB, live {:.1} MiB, {:.1} MiB in {} allocations", mib(s.peak), mib(s.live), mib(s.total), s.count ); } } impl Drop for Phase { fn drop(&mut self) { if let Some(t) = self.started { let ms = t.elapsed().as_secs_f64() * 1000.0; match (self.mem, crate::alloc_stats::stats()) { (Some(a), Some(b)) => eprintln!( "timing {:<28} {:>9.2} ms live {:>8.1} MiB peak {:>8.1} MiB +{:.1} MiB in {} allocs", self.name, ms, mib(b.live), mib(b.peak), mib(b.total - a.total), b.count - a.count ), _ => eprintln!("timing {:<28} {:>9.2} ms", self.name, ms), } } } } static TOTALS: std::sync::Mutex> = std::sync::Mutex::new(Vec::new()); /// Add `d` to the running total for `name`, for a phase repeated many /// times (once per imported commit, say); `report_totals` prints them. pub fn add(name: &'static str, d: std::time::Duration) { if !enabled() { return; } let mut t = TOTALS.lock().unwrap_or_else(|e| e.into_inner()); match t.iter_mut().find(|(n, _)| *n == name) { Some((_, total)) => *total += d, None => t.push((name, d)), } } /// Print and clear the totals `add` gathered. pub fn report_totals() { if !enabled() { return; } let t = std::mem::take(&mut *TOTALS.lock().unwrap_or_else(|e| e.into_inner())); for (name, d) in t { record(name, d); } } /// Times from one point to the next, adding each interval to a total. pub struct Laps(Option); impl Laps { pub fn start() -> Laps { Laps(enabled().then(Instant::now)) } /// Add the time since the last lap to `name`'s total. pub fn lap(&mut self, name: &'static str) { if let Some(t) = &mut self.0 { let now = Instant::now(); add(name, now - *t); *t = now; } } }