flux_middle/
timings.rs

1use std::{
2    fs, io,
3    sync::Mutex,
4    time::{Duration, Instant},
5};
6
7use flux_config as config;
8use itertools::Itertools;
9use rustc_hir::def_id::{DefId, LOCAL_CRATE, LocalDefId};
10use rustc_middle::ty::TyCtxt;
11use serde::Serialize;
12
13use crate::FixpointQueryKind;
14
15static TIMINGS: Mutex<Vec<Entry>> = Mutex::new(Vec::new());
16
17pub enum TimingKind {
18    /// Time taken to check the body of a function
19    CheckFn(LocalDefId),
20    /// Time taken to run a single fixpoint query
21    FixpointQuery(DefId, FixpointQueryKind),
22}
23
24pub fn enter<R>(tcx: TyCtxt, f: impl FnOnce() -> R) -> R {
25    if !config::timings() {
26        return f();
27    }
28    let start = Instant::now();
29    let r = f();
30    print_and_dump_report(tcx, start.elapsed(), std::mem::take(&mut *TIMINGS.lock().unwrap()))
31        .unwrap();
32    r
33}
34
35#[derive(Serialize)]
36struct TimingsDump {
37    /// Total time taken to run the complte Flux analysis on the crate
38    total: ms,
39    /// Per-function analysis timings
40    functions: Vec<FuncTiming>,
41    /// Per-query execution timings
42    queries: Vec<QueryTiming>,
43}
44
45#[derive(Serialize)]
46struct FuncTiming {
47    def_path: String,
48    time_ms: ms,
49}
50
51#[derive(Serialize)]
52struct QueryTiming {
53    task_key: String,
54    time_ms: ms,
55}
56
57fn snd<A, B: Copy>(&(_, b): &(A, B)) -> B {
58    b
59}
60
61fn print_and_dump_report(tcx: TyCtxt, total: Duration, timings: Vec<Entry>) -> io::Result<()> {
62    let mut functions = vec![];
63    let mut queries = vec![];
64    for timing in timings {
65        match timing.kind {
66            TimingKind::CheckFn(local_def_id) => {
67                let def_path = tcx.def_path_str(local_def_id);
68                functions.push((def_path, timing.duration));
69            }
70            TimingKind::FixpointQuery(def_id, kind) => {
71                let key = kind.task_key(tcx, def_id);
72                queries.push((key, timing.duration));
73            }
74        }
75    }
76    functions.sort_by_key(snd);
77    functions.reverse();
78
79    queries.sort_by_key(snd);
80    queries.reverse();
81
82    print_report(&functions, total);
83    dump_timings(
84        tcx,
85        TimingsDump {
86            total: ms(total),
87            functions: functions
88                .into_iter()
89                .map(|(def_path, time)| FuncTiming { def_path, time_ms: ms(time) })
90                .collect(),
91            queries: queries
92                .into_iter()
93                .map(|(task_key, time)| QueryTiming { task_key, time_ms: ms(time) })
94                .collect(),
95        },
96    )
97}
98
99fn print_report(functions: &[(String, Duration)], total: Duration) {
100    let stats = stats(&functions.iter().map(snd).collect_vec());
101    eprintln!();
102    eprintln!("───────────────────── Timing Report ────────────────────────");
103    eprintln!("Total running time: {:>40}", fmt_duration(total));
104    eprintln!("Functions checked:  {:>40}", stats.count);
105    eprintln!("Min:                {:>40}", fmt_duration(stats.min));
106    eprintln!("Max:                {:>40}", fmt_duration(stats.max));
107    eprintln!("Mean:               {:>40}", fmt_duration(stats.mean));
108    eprintln!("Std. Dev.:          {:>40}", fmt_duration(stats.standard_deviation));
109
110    let top5 = functions.iter().take(5).cloned().collect_vec();
111    if !top5.is_empty() {
112        eprintln!("────────────────────────────────────────────────────────────");
113        eprintln!("Top 5 Functions ");
114        for (def_path, duration) in top5 {
115            let len = def_path.len();
116            if len > 46 {
117                eprintln!(
118                    "• …{} {:>width$}",
119                    &def_path[len - 46..],
120                    fmt_duration(duration),
121                    width = 10
122                );
123            } else {
124                eprintln!(
125                    "• {def_path} {:>width$}",
126                    fmt_duration(duration),
127                    width = 60 - def_path.len() - 3
128                );
129            }
130        }
131    }
132    eprintln!("────────────────────────────────────────────────────────────");
133}
134
135fn dump_timings(tcx: TyCtxt, timings: TimingsDump) -> io::Result<()> {
136    let crate_name = tcx.crate_name(LOCAL_CRATE);
137    fs::create_dir_all(config::log_dir())?;
138    let path = config::log_dir().join(format!("{crate_name}-timings.json"));
139    let mut file = fs::File::create(path)?;
140    serde_json::to_writer(&mut file, &timings)?;
141    Ok(())
142}
143
144pub fn time_it<R>(kind: TimingKind, f: impl FnOnce() -> R) -> R {
145    if !config::timings() {
146        return f();
147    }
148    let start = Instant::now();
149    let r = f();
150    TIMINGS
151        .lock()
152        .unwrap()
153        .push(Entry { duration: start.elapsed(), kind });
154    r
155}
156
157fn stats(durations: &[Duration]) -> Stats {
158    let count = durations.len() as u32;
159    if count == 0 {
160        return Stats::default();
161    }
162    let sum: Duration = durations.iter().sum();
163    let mean = sum / count;
164
165    let meanf = mean.as_millis() as f64;
166    let mut sum_of_squares = 0.0;
167    let mut max = Duration::ZERO;
168    let mut min = Duration::MAX;
169    for duration in durations {
170        let diff = duration.as_millis() as f64 - meanf;
171        sum_of_squares += diff * diff;
172        max = max.max(*duration);
173        min = min.min(*duration);
174    }
175    let standard_deviation = Duration::from_millis((sum_of_squares / count as f64).sqrt() as u64);
176
177    Stats { count, max, min, mean, standard_deviation }
178}
179
180#[derive(Default)]
181struct Stats {
182    count: u32,
183    max: Duration,
184    min: Duration,
185    mean: Duration,
186    standard_deviation: Duration,
187}
188
189struct Entry {
190    duration: Duration,
191    kind: TimingKind,
192}
193
194#[allow(non_camel_case_types)]
195#[derive(Clone, Copy, Serialize)]
196#[serde(into = "u128")]
197struct ms(Duration);
198
199impl From<ms> for u128 {
200    fn from(value: ms) -> Self {
201        value.0.as_millis()
202    }
203}
204
205fn fmt_duration(duration: Duration) -> String {
206    let nanos = duration.as_nanos();
207
208    if nanos < 1_000 {
209        format!("{}ns", nanos)
210    } else if nanos < 1_000_000 {
211        format!("{:.2}µs", nanos as f64 / 1_000.0)
212    } else if nanos < 1_000_000_000 {
213        format!("{:.2}ms", nanos as f64 / 1_000_000.0)
214    } else if nanos < 60_000_000_000 {
215        format!("{:.2}s", nanos as f64 / 1_000_000_000.0)
216    } else {
217        let seconds = duration.as_secs();
218        let minutes = seconds / 60;
219        let seconds_remainder = seconds % 60;
220
221        if minutes < 60 {
222            format!("{}m {}s", minutes, seconds_remainder)
223        } else {
224            let hours = minutes / 60;
225            let minutes_remainder = minutes % 60;
226
227            if hours < 24 {
228                format!("{}h {}m {}s", hours, minutes_remainder, seconds_remainder)
229            } else {
230                let days = hours / 24;
231                let hours_remainder = hours % 24;
232                format!(
233                    "{}d {}h {}m {}s",
234                    days, hours_remainder, minutes_remainder, seconds_remainder
235                )
236            }
237        }
238    }
239}
flux_middle/timings.rs

flux_middle/
timings.rs
