charon_lib/
timing.rs

1//! Lightweight, opt-in timing instrumentation.
2//!
3//! Enabled by setting the `CHARON_TIMINGS` environment variable. Set it to `1` to get a
4//! human-readable report on stderr at the end of the run; set it to a file path to additionally
5//! append the measurements as csv lines to that file.
6//!
7//! Scopes can be nested: we report both the total (wall) time spent in a scope and the "self"
8//! time, i.e. the time not spent inside a nested instrumented scope.
9use std::cell::RefCell;
10use std::collections::HashMap;
11use std::io::Write;
12use std::sync::{LazyLock, Mutex};
13use std::time::{Duration, Instant};
14
15/// Whether timing is enabled at all.
16static SETTING: LazyLock<Option<String>> = LazyLock::new(|| std::env::var("CHARON_TIMINGS").ok());
17
18pub fn enabled() -> bool {
19    SETTING.is_some()
20}
21
22#[derive(Default, Clone, Copy)]
23pub struct Measure {
24    pub total: Duration,
25    pub own: Duration,
26    pub count: u64,
27}
28
29/// Measurements are aggregated globally (translation is single-threaded but rustc may call us from
30/// several threads, hence the mutex).
31static MEASURES: LazyLock<Mutex<HashMap<String, Measure>>> = LazyLock::new(Default::default);
32
33thread_local! {
34    /// Time spent in nested scopes, for the currently-running scope.
35    static NESTED: RefCell<Vec<Duration>> = const { RefCell::new(Vec::new()) };
36}
37
38/// A running measurement; the timing is recorded when this is dropped.
39pub struct Guard {
40    name: &'static str,
41    /// Only used to give a more precise name than `name` when relevant.
42    suffix: Option<String>,
43    start: Instant,
44}
45
46/// Time the given scope, if timings are enabled.
47pub fn scope(name: &'static str) -> Option<Guard> {
48    scope_with(name, None)
49}
50
51/// Same as [`scope`] but allows refining the name dynamically.
52pub fn scope_with(name: &'static str, suffix: Option<String>) -> Option<Guard> {
53    if !enabled() {
54        return None;
55    }
56    NESTED.with_borrow_mut(|stack| stack.push(Duration::ZERO));
57    Some(Guard {
58        name,
59        suffix,
60        start: Instant::now(),
61    })
62}
63
64impl Drop for Guard {
65    fn drop(&mut self) {
66        let elapsed = self.start.elapsed();
67        let nested = NESTED.with_borrow_mut(|stack| {
68            let nested = stack.pop().unwrap_or_default();
69            if let Some(parent) = stack.last_mut() {
70                *parent += elapsed;
71            }
72            nested
73        });
74        let long_key = self
75            .suffix
76            .as_ref()
77            .map(|suffix| format!("{}/{suffix}", self.name));
78        let key: &str = long_key.as_deref().unwrap_or(self.name);
79        let mut measures = MEASURES.lock().unwrap();
80        // Avoid allocating a fresh `String` on each call.
81        if !measures.contains_key(key) {
82            measures.insert(key.to_owned(), Measure::default());
83        }
84        let entry = measures.get_mut(key).unwrap();
85        entry.total += elapsed;
86        entry.own += elapsed.saturating_sub(nested);
87        entry.count += 1;
88    }
89}
90
91/// Same as [`scope_with`] but only computes the suffix if timings are enabled.
92pub fn scope_lazy(name: &'static str, suffix: impl FnOnce() -> String) -> Option<Guard> {
93    if !enabled() {
94        return None;
95    }
96    scope_with(name, Some(suffix()))
97}
98
99/// Time the given closure.
100pub fn time<T>(name: &'static str, f: impl FnOnce() -> T) -> T {
101    let _guard = scope(name);
102    f()
103}
104
105/// Print the timing report on stderr, and append it to the file given in `CHARON_TIMINGS` if it
106/// isn't `1`.
107pub fn report(crate_name: &str) {
108    let Some(setting) = SETTING.as_ref() else {
109        return;
110    };
111    let measures = MEASURES.lock().unwrap();
112    let mut entries: Vec<(&String, &Measure)> = measures.iter().collect();
113    entries.sort_by_key(|(name, m)| (std::cmp::Reverse(m.own), (*name).clone()));
114
115    let mut out = String::new();
116    out += &format!("\n=== charon timings for crate `{crate_name}` ===\n");
117    out += &format!(
118        "{:<60} {:>12} {:>12} {:>10}\n",
119        "scope", "total (ms)", "self (ms)", "calls"
120    );
121    for (name, m) in &entries {
122        out += &format!(
123            "{:<60} {:>12.2} {:>12.2} {:>10}\n",
124            name,
125            m.total.as_secs_f64() * 1000.,
126            m.own.as_secs_f64() * 1000.,
127            m.count
128        );
129    }
130    eprint!("{out}");
131
132    if setting != "1"
133        && let Ok(mut file) = std::fs::OpenOptions::new()
134            .create(true)
135            .append(true)
136            .open(setting)
137    {
138        for (name, m) in &entries {
139            let _ = writeln!(
140                file,
141                "{crate_name},{name},{:.3},{:.3},{}",
142                m.total.as_secs_f64() * 1000.,
143                m.own.as_secs_f64() * 1000.,
144                m.count
145            );
146        }
147    }
148}
charon_lib/timing.rs

charon_lib/
timing.rs
