timing.rs 68.0%

51 of 75 lines run, 21 of 30 functions · run #379 on main · run missed

//! 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<bool> = 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 <name> <ms>` when dropped, if timings are on.
pub struct Phase {
    name: &'static str,
    started: Option<Instant>,
    /// Allocator counters at the start, when counting.
    mem: Option<crate::alloc_stats::Stats>,
}

/// 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<Vec<(&'static str, std::time::Duration)>> =
    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<Instant>);

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;
        }
    }
}

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	151741×	pub fn enabled() -> bool {
11		static ON: OnceLock<bool> = OnceLock::new();
12	151741×	*ON.get_or_init(\|\| std::env::var_os("OXY_TIMINGS").is_some_and(\|v\| !v.is_empty() && v != "0"))
13	151741×	}
14
15		/// Report a duration measured by hand (several intervals summed), if timings are on.
16	11676×	pub fn record(name: &str, d: std::time::Duration) {
17	11676×	if enabled() {
18	6×	eprintln!("timing {:<28} {:>9.2} ms", name, d.as_secs_f64() * 1000.0);
19	11670×	}
20	11676×	}
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	100644×	pub fn phase(name: &'static str) -> Phase {
32	100644×	let on = enabled();
33		Phase {
34	100644×	name,
35	100644×	started: on.then(Instant::now),
36	100644×	mem: if on {
37	82×	crate::alloc_stats::stats()
38		} else {
39	100562×	None
40		},
41		}
42	100644×	}
43
44	0×	fn mib(n: usize) -> f64 {
45	0×	n as f64 / (1024.0 * 1024.0)
46	0×	}
47
48		/// The allocator's counters as one line, when counting: for the end of a
49		/// command.
50	150×	pub fn memory_summary() {
51	150×	if let (true, Some(s)) = (enabled(), crate::alloc_stats::stats()) {
52	0×	eprintln!(
53	0×	"memory peak {:.1} MiB, live {:.1} MiB, {:.1} MiB in {} allocations",
54	0×	mib(s.peak),
55	0×	mib(s.live),
56	0×	mib(s.total),
57	0×	s.count
58	0×	);
59	150×	}
60	150×	}
61
62		impl Drop for Phase {
63	100642×	fn drop(&mut self) {
64	100642×	if let Some(t) = self.started {
65	82×	let ms = t.elapsed().as_secs_f64() * 1000.0;
66	82×	match (self.mem, crate::alloc_stats::stats()) {
67	0×	(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	0×	mib(b.live),
72	0×	mib(b.peak),
73	0×	mib(b.total - a.total),
74	0×	b.count - a.count
75		),
76	82×	_ => eprintln!("timing {:<28} {:>9.2} ms", self.name, ms),
77		}
78	100560×	}
79	100642×	}
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	494×	pub fn add(name: &'static str, d: std::time::Duration) {
88	494×	if !enabled() {
89	482×	return;
90	12×	}
91	12×	let mut t = TOTALS.lock().unwrap_or_else(\|e\| e.into_inner());
92	30×	match t.iter_mut().find(\|(n, _)\| *n == name) {
93	0×	Some((_, total)) => *total += d,
94	12×	None => t.push((name, d)),
95		}
96	494×	}
97
98		/// Print and clear the totals `add` gathered.
99	579×	pub fn report_totals() {
100	579×	if !enabled() {
101	579×	return;
102	0×	}
103	0×	let t = std::mem::take(&mut *TOTALS.lock().unwrap_or_else(\|e\| e.into_inner()));
104	0×	for (name, d) in t {
105	0×	record(name, d);
106	0×	}
107	579×	}
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	3141×	pub fn start() -> Laps {
114	3141×	Laps(enabled().then(Instant::now))
115	3141×	}
116		/// Add the time since the last lap to `name`'s total.
117	14636×	pub fn lap(&mut self, name: &'static str) {
118	14636×	if let Some(t) = &mut self.0 {
119	12×	let now = Instant::now();
120	12×	add(name, now - *t);
121	12×	*t = now;
122	14624×	}
123	14636×	}
124		}

`/`	Search
`g` `c`	Code
`g` `h`	History
`g` `b`	Bookmarks
`g` `t`	Trust
`y`	Permalink to this state (files and trees)
`?`	This sheet

Coverage / crates/oxy-core/src/timing.rs 68.0%

Keyboard