flux_middle/
metrics.rs

1use std::{
2    fs,
3    io::{self, Write as _},
4    sync::{Mutex, atomic::AtomicU32},
5    time::{Duration, Instant},
6};
7
8use flux_config as config;
9use itertools::Itertools;
10use rustc_hir::def_id::{DefId, LOCAL_CRATE, LocalDefId};
11use rustc_middle::ty::TyCtxt;
12use serde::Serialize;
13
14use crate::FixpointQueryKind;
15
16const BOLD: anstyle::Style = anstyle::Style::new().bold();
17const GREY: anstyle::Style = anstyle::AnsiColor::BrightBlack.on_default();
18
19pub fn print_summary(total_time: Duration) -> io::Result<()> {
20    let mut stderr = anstream::Stderr::always(std::io::stderr());
21    writeln!(
22        &mut stderr,
23        "{BOLD}summary.{BOLD:#} {} functions processed: {} checked; {} trusted; {} ignored. {} constraints solved. Finished in {}{GREY:#}",
24        METRICS.get(Metric::FnTotal),
25        METRICS.get(Metric::FnChecked),
26        METRICS.get(Metric::FnTrusted),
27        METRICS.get(Metric::FnIgnored),
28        METRICS.get(Metric::CsTotal),
29        fmt_duration(total_time),
30    )
31}
32
33static METRICS: Metrics = Metrics::new();
34
35#[repr(u8)]
36pub enum Metric {
37    /// number of functions (i.e., `DefId`s) processed
38    FnTotal,
39    /// number of "trusted" functions
40    FnTrusted,
41    /// number of "ignored" functions
42    FnIgnored,
43    /// number of functions that were actually checked
44    FnChecked,
45    /// number of cached queries
46    FnCached,
47    /// number of trivial queries
48    FnTrivial,
49    /// number of concrete constraints
50    CsTotal,
51    /// number of unsat constraints
52    CsError,
53}
54
55struct Metrics {
56    counts: [AtomicU32; 8],
57}
58
59impl Metrics {
60    const fn new() -> Self {
61        Self {
62            counts: [
63                AtomicU32::new(0),
64                AtomicU32::new(0),
65                AtomicU32::new(0),
66                AtomicU32::new(0),
67                AtomicU32::new(0),
68                AtomicU32::new(0),
69                AtomicU32::new(0),
70                AtomicU32::new(0),
71            ],
72        }
73    }
74
75    fn incr(&self, metric: Metric, val: u32) {
76        self.counts[metric as usize].fetch_add(val, std::sync::atomic::Ordering::Relaxed);
77    }
78
79    fn get(&self, metric: Metric) -> u32 {
80        self.counts[metric as usize].load(std::sync::atomic::Ordering::Relaxed)
81    }
82}
83
84pub fn incr_metric(metric: Metric, val: u32) {
85    METRICS.incr(metric, val);
86}
87
88pub fn incr_metric_if(cond: bool, metric: Metric) {
89    if cond {
90        incr_metric(metric, 1);
91    }
92}
93
94static TIMINGS: Mutex<Vec<Entry>> = Mutex::new(Vec::new());
95
96pub enum TimingKind {
97    /// Total time taken to run the complete Flux analysis on the crate
98    Total,
99    /// Time taken to check the body of a function
100    CheckFn(LocalDefId),
101    /// Time taken to run a single fixpoint query
102    FixpointQuery(DefId, FixpointQueryKind),
103}
104
105#[derive(Serialize)]
106struct TimingsDump {
107    /// Total time taken to run the complte Flux analysis on the crate
108    total: ms,
109    /// Per-function analysis timings
110    functions: Vec<FuncTiming>,
111    /// Per-query execution timings
112    queries: Vec<QueryTiming>,
113}
114
115#[derive(Serialize)]
116struct FuncTiming {
117    def_path: String,
118    time_ms: ms,
119}
120
121#[derive(Serialize)]
122struct QueryTiming {
123    task_key: String,
124    time_ms: ms,
125}
126
127fn snd<A, B: Copy>(&(_, b): &(A, B)) -> B {
128    b
129}
130
131pub fn print_and_dump_timings(tcx: TyCtxt) -> io::Result<()> {
132    if !config::timings() {
133        return Ok(());
134    }
135
136    let timings = std::mem::take(&mut *TIMINGS.lock().unwrap());
137    let mut functions = vec![];
138    let mut queries = vec![];
139    let mut total = Duration::from_secs(0);
140    for timing in timings {
141        match timing.kind {
142            TimingKind::CheckFn(local_def_id) => {
143                let def_path = tcx.def_path_str(local_def_id);
144                functions.push((def_path, timing.duration));
145            }
146            TimingKind::FixpointQuery(def_id, kind) => {
147                let key = kind.task_key(tcx, def_id);
148                queries.push((key, timing.duration));
149            }
150            TimingKind::Total => {
151                // This should only appear once
152                total = timing.duration;
153            }
154        }
155    }
156    functions.sort_by_key(snd);
157    functions.reverse();
158
159    queries.sort_by_key(snd);
160    queries.reverse();
161
162    print_report(&functions, total);
163    dump_timings(
164        tcx,
165        TimingsDump {
166            total: ms(total),
167            functions: functions
168                .into_iter()
169                .map(|(def_path, time)| FuncTiming { def_path, time_ms: ms(time) })
170                .collect(),
171            queries: queries
172                .into_iter()
173                .map(|(task_key, time)| QueryTiming { task_key, time_ms: ms(time) })
174                .collect(),
175        },
176    )
177}
178
179fn print_report(functions: &[(String, Duration)], total: Duration) {
180    let stats = stats(&functions.iter().map(snd).collect_vec());
181    eprintln!();
182    eprintln!("───────────────────── Timing Report ────────────────────────");
183    eprintln!("Total running time: {:>40}", fmt_duration(total));
184    eprintln!("Functions checked:  {:>40}", stats.count);
185    eprintln!("Min:                {:>40}", fmt_duration(stats.min));
186    eprintln!("Max:                {:>40}", fmt_duration(stats.max));
187    eprintln!("Mean:               {:>40}", fmt_duration(stats.mean));
188    eprintln!("Std. Dev.:          {:>40}", fmt_duration(stats.standard_deviation));
189
190    let top5 = functions.iter().take(5).cloned().collect_vec();
191    if !top5.is_empty() {
192        eprintln!("────────────────────────────────────────────────────────────");
193        eprintln!("Top 5 Functions ");
194        for (def_path, duration) in top5 {
195            let len = def_path.len();
196            if len > 46 {
197                eprintln!(
198                    "• …{} {:>width$}",
199                    &def_path[len - 46..],
200                    fmt_duration(duration),
201                    width = 10
202                );
203            } else {
204                eprintln!(
205                    "• {def_path} {:>width$}",
206                    fmt_duration(duration),
207                    width = 60 - def_path.len() - 3
208                );
209            }
210        }
211    }
212    eprintln!("────────────────────────────────────────────────────────────");
213}
214
215fn dump_timings(tcx: TyCtxt, timings: TimingsDump) -> io::Result<()> {
216    let crate_name = tcx.crate_name(LOCAL_CRATE);
217    fs::create_dir_all(config::log_dir())?;
218    let path = config::log_dir().join(format!("{crate_name}-timings.json"));
219    let mut file = fs::File::create(path)?;
220    serde_json::to_writer(&mut file, &timings)?;
221    Ok(())
222}
223
224pub fn time_it<R>(kind: TimingKind, f: impl FnOnce() -> R) -> R {
225    if !config::timings() {
226        return f();
227    }
228    let start = Instant::now();
229    let r = f();
230    TIMINGS
231        .lock()
232        .unwrap()
233        .push(Entry { duration: start.elapsed(), kind });
234    r
235}
236
237fn stats(durations: &[Duration]) -> TimingStats {
238    let count = durations.len() as u32;
239    if count == 0 {
240        return TimingStats::default();
241    }
242    let sum: Duration = durations.iter().sum();
243    let mean = sum / count;
244
245    let meanf = mean.as_millis() as f64;
246    let mut sum_of_squares = 0.0;
247    let mut max = Duration::ZERO;
248    let mut min = Duration::MAX;
249    for duration in durations {
250        let diff = duration.as_millis() as f64 - meanf;
251        sum_of_squares += diff * diff;
252        max = max.max(*duration);
253        min = min.min(*duration);
254    }
255    let standard_deviation = Duration::from_millis((sum_of_squares / count as f64).sqrt() as u64);
256
257    TimingStats { count, max, min, mean, standard_deviation }
258}
259
260#[derive(Default)]
261struct TimingStats {
262    count: u32,
263    max: Duration,
264    min: Duration,
265    mean: Duration,
266    standard_deviation: Duration,
267}
268
269struct Entry {
270    duration: Duration,
271    kind: TimingKind,
272}
273
274#[allow(non_camel_case_types)]
275#[derive(Clone, Copy, Serialize)]
276#[serde(into = "u128")]
277struct ms(Duration);
278
279impl From<ms> for u128 {
280    fn from(value: ms) -> Self {
281        value.0.as_millis()
282    }
283}
284
285fn fmt_duration(duration: Duration) -> String {
286    let nanos = duration.as_nanos();
287
288    if nanos < 1_000 {
289        format!("{nanos}ns")
290    } else if nanos < 1_000_000 {
291        format!("{:.2}µs", nanos as f64 / 1_000.0)
292    } else if nanos < 1_000_000_000 {
293        format!("{:.2}ms", nanos as f64 / 1_000_000.0)
294    } else if nanos < 60_000_000_000 {
295        format!("{:.2}s", nanos as f64 / 1_000_000_000.0)
296    } else {
297        let seconds = duration.as_secs();
298        let minutes = seconds / 60;
299        let seconds_remainder = seconds % 60;
300
301        if minutes < 60 {
302            format!("{minutes}m {seconds_remainder}s")
303        } else {
304            let hours = minutes / 60;
305            let minutes_remainder = minutes % 60;
306
307            if hours < 24 {
308                format!("{hours}h {minutes_remainder}m {seconds_remainder}s")
309            } else {
310                let days = hours / 24;
311                let hours_remainder = hours % 24;
312                format!("{days}d {hours_remainder}h {minutes_remainder}m {seconds_remainder}s",)
313            }
314        }
315    }
316}
flux_middle/metrics.rs

flux_middle/
metrics.rs
