kui_trace/
diff.rs

1//! Two recordings compared (ADR 0058, decision 12): each span's and
2//! phase's spread, the burns, the gaps and the counters, before and after
3//! — `kui-trace diff A B`, with `--fail-over` a CI's threshold.
4//!
5//! Spans are matched by their name's text and origin, never by id: ids
6//! and name ids differ between two recordings of one session. What a span
7//! or a gap costs is a frame's share (its total over the frames), so two
8//! recordings of one script compare even when one ran a few frames
9//! longer.
10//!
11//! [`Report::worst_growth`] reads only the rows that say what a frame
12//! costs and that were big enough before to say it ([`Unit::counts`]):
13//! a time of at least [`NOISE_US`] (below it, a timer's jitter is a large
14//! share of nothing), and a rate of at least one a frame. A maximum, a
15//! count, a share and vsync's wait are shown and never counted: one
16//! outlier frame, a recording's length and a faster render (which waits
17//! longer) are not regressions.
18
19use std::collections::HashMap;
20use std::fmt::Write;
21
22use crate::adapters::origin_label;
23use crate::analysis::{self, Phases};
24use crate::model::Trace;
25
26/// Below this many µs before, a time row's growth is noise.
27pub const NOISE_US: f64 = 50.0;
28/// Below this many a frame before, a rate row's growth is noise.
29pub const NOISE_RATE: f64 = 1.0;
30/// The growth [`Report::text`] marks.
31pub const MARK: f64 = 0.10;
32
33/// What a row counts.
34#[derive(Clone, Copy, Debug, PartialEq, Eq)]
35pub enum Unit {
36    /// µs a frame costs: an average, a p95, a share of a total.
37    Us,
38    /// µs shown and not counted: a maximum, vsync's wait, time asleep.
39    UsShown,
40    /// How many a frame: calls, a counter's average.
41    Rate,
42    /// How many in the recording: frames, burns.
43    Count,
44    /// A fraction of the frames.
45    Share,
46}
47
48impl Unit {
49    /// Whether a row of this unit, `before` this, counts towards
50    /// [`Report::worst_growth`].
51    pub fn counts(self, before: f64) -> bool {
52        match self {
53            Unit::Us => before >= NOISE_US,
54            Unit::Rate => before >= NOISE_RATE,
55            Unit::UsShown | Unit::Count | Unit::Share => false,
56        }
57    }
58
59    fn show(self, v: f64) -> String {
60        match self {
61            Unit::Us | Unit::UsShown => format!("{:.3} ms", v / 1000.0),
62            Unit::Rate => format!("{v:.2}"),
63            Unit::Count => format!("{v:.0}"),
64            Unit::Share => format!("{:.1}%", v * 100.0),
65        }
66    }
67}
68
69/// What changed from `a` to `b`.
70#[derive(Clone, Debug, Default, PartialEq)]
71pub struct Report {
72    /// `(what, before, after)`, µs or a count.
73    pub rows: Vec<(String, f64, f64)>,
74    /// Each row's unit, by index; a row past its end is [`Unit::Us`].
75    pub units: Vec<Unit>,
76}
77
78impl Report {
79    /// Adds a row.
80    pub fn push(&mut self, what: impl Into<String>, unit: Unit, before: f64, after: f64) {
81        self.rows.push((what.into(), before, after));
82        self.units.push(unit);
83    }
84
85    /// Row `i`'s unit.
86    pub fn unit(&self, i: usize) -> Unit {
87        self.units.get(i).copied().unwrap_or(Unit::Us)
88    }
89
90    /// Row `i`'s growth as a fraction of its before, when it counts.
91    pub fn growth(&self, i: usize) -> Option<f64> {
92        let (_, a, b) = self.rows[i];
93        self.unit(i).counts(a).then(|| (b - a) / a)
94    }
95
96    /// The report as text, a row a line, marking a counted row that grew
97    /// or shrank past [`MARK`].
98    pub fn text(&self) -> String {
99        self.text_with(MARK)
100    }
101
102    /// The report as text, marking a counted row whose change passes
103    /// `threshold` (a fraction): `▲` grew, `▼` shrank.
104    pub fn text_with(&self, threshold: f64) -> String {
105        let cells: Vec<[String; 4]> = self
106            .rows
107            .iter()
108            .enumerate()
109            .map(|(i, (what, a, b))| {
110                let u = self.unit(i);
111                let change = if *a == 0.0 && *b == 0.0 {
112                    String::new()
113                } else if *a == 0.0 {
114                    "new".into()
115                } else {
116                    let g = (b - a) / a;
117                    let mark = match self.growth(i) {
118                        Some(g) if g > threshold => " ▲",
119                        Some(g) if g < -threshold => " ▼",
120                        _ => "",
121                    };
122                    format!("{:+.1}%{mark}", g * 100.0)
123                };
124                [what.clone(), u.show(*a), u.show(*b), change]
125            })
126            .collect();
127        let head = ["what", "before", "after", "change"].map(String::from);
128        let width = |k: usize| {
129            cells
130                .iter()
131                .chain(std::iter::once(&head))
132                .map(|c| c[k].chars().count())
133                .max()
134                .unwrap_or(0)
135        };
136        let w = [width(0), width(1), width(2)];
137        let mut out = String::new();
138        for c in std::iter::once(&head).chain(cells.iter()) {
139            let line = format!(
140                "{:<w0$}  {:>w1$}  {:>w2$}  {}",
141                c[0],
142                c[1],
143                c[2],
144                c[3],
145                w0 = w[0],
146                w1 = w[1],
147                w2 = w[2]
148            );
149            let _ = writeln!(out, "{}", line.trim_end());
150        }
151        out
152    }
153
154    /// The largest growth of any row, as a fraction of its before: over
155    /// the rows that count ([`Unit::counts`]), `0` when none does.
156    pub fn worst_growth(&self) -> f64 {
157        (0..self.rows.len())
158            .filter_map(|i| self.growth(i))
159            .fold(None, |m: Option<f64>, g| Some(m.map_or(g, |m| m.max(g))))
160            .unwrap_or(0.0)
161    }
162}
163
164/// A recording's rows, in the order a report shows them.
165fn rows(trace: &Trace) -> Vec<(String, Unit, f64)> {
166    let tl = trace.timeline();
167    let n = tl.frames.len();
168    let per = n.max(1) as f64;
169    let mut out: Vec<(String, Unit, f64)> = Vec::new();
170    let mut push = |what: String, u: Unit, v: f64| out.push((what, u, v));
171
172    push("frames".into(), Unit::Count, n as f64);
173    let phases: Vec<Phases> = (0..n).map(|i| analysis::phases(&tl, i, trace)).collect();
174    for (k, (name, _)) in Phases::default().named().iter().enumerate() {
175        let v: Vec<u64> = phases.iter().map(|p| p.named()[k].1).collect();
176        let (avg, p95, max) = analysis::spread(&v);
177        let u = if *name == "vsync wait" {
178            Unit::UsShown
179        } else {
180            Unit::Us
181        };
182        push(format!("phase {name} avg"), u, avg);
183        push(format!("phase {name} p95"), u, p95 as f64);
184        push(format!("phase {name} max"), Unit::UsShown, max as f64);
185    }
186    let work: Vec<u64> = tl.frames.iter().map(|f| f.work_us()).collect();
187    let (avg, p95, max) = analysis::spread(&work);
188    push("frame work avg".into(), Unit::Us, avg);
189    push("frame work p95".into(), Unit::Us, p95 as f64);
190    push("frame work max".into(), Unit::UsShown, max as f64);
191    let traced = tl.frames.iter().filter(|f| f.unchanged.is_some()).count();
192    let unchanged = tl
193        .frames
194        .iter()
195        .filter(|f| f.unchanged == Some(true))
196        .count();
197    push(
198        "unchanged share".into(),
199        Unit::Share,
200        unchanged as f64 / traced.max(1) as f64,
201    );
202    let burns = analysis::burns(&tl, trace);
203    push("burns".into(), Unit::Count, burns.len() as f64);
204    push(
205        "burn frames".into(),
206        Unit::Count,
207        burns.iter().map(|b| b.len()).sum::<usize>() as f64,
208    );
209    let g = analysis::gaps(&tl, trace);
210    push("gap µs/frame".into(), Unit::UsShown, g.total as f64 / per);
211    push(
212        "gap handlers µs/frame".into(),
213        Unit::Us,
214        g.handlers as f64 / per,
215    );
216    push(
217        "gap asleep µs/frame".into(),
218        Unit::UsShown,
219        g.asleep as f64 / per,
220    );
221    push("gap busy µs/frame".into(), Unit::Us, g.busy as f64 / per);
222    for st in analysis::by_span(&tl, &tl.spans) {
223        let what = format!(
224            "span {} [{}]",
225            trace.name(st.name),
226            origin_label(trace, st.origin)
227        );
228        push(
229            format!("{what} calls/frame"),
230            Unit::Rate,
231            st.calls as f64 / per,
232        );
233        push(format!("{what} µs/frame"), Unit::Us, st.total as f64 / per);
234        push(format!("{what} worst"), Unit::UsShown, st.worst as f64);
235    }
236    for (name, avg, _) in analysis::counters(&tl) {
237        push(format!("counter {} avg", trace.name(name)), Unit::Rate, avg);
238    }
239    out
240}
241
242/// `a` against `b`.
243pub fn diff(a: &Trace, b: &Trace) -> Report {
244    let ra = rows(a);
245    let rb = rows(b);
246    let after: HashMap<&str, f64> = rb.iter().map(|(w, _, v)| (w.as_str(), *v)).collect();
247    let before: HashMap<&str, f64> = ra.iter().map(|(w, _, v)| (w.as_str(), *v)).collect();
248    let mut report = Report::default();
249    for (what, u, v) in &ra {
250        report.push(
251            what.clone(),
252            *u,
253            *v,
254            after.get(what.as_str()).copied().unwrap_or(0.0),
255        );
256    }
257    for (what, u, v) in &rb {
258        if !before.contains_key(what.as_str()) {
259            report.push(what.clone(), *u, 0.0, *v);
260        }
261    }
262    report
263}
264
265#[cfg(test)]
266mod tests {
267    use super::*;
268    use crate::{Origin, Record, Span, Track};
269
270    /// `n` frames 16 ms apart, each a `build` of `build_us` with a `rows`
271    /// child of `rows_us`, a counter, and a present.
272    fn recording(n: u64, build_us: u64, rows_us: u64) -> Trace {
273        let mut t = Trace::new();
274        let (key, _) = t.names.get("key");
275        let (build, _) = t.names.get("build");
276        let (rows, _) = t.names.get("rows");
277        let (laid, _) = t.names.get("laid");
278        for i in 0..n {
279            let at = i * 16_000;
280            t.records.push(Record::FrameBegin {
281                t: at,
282                frame: i + 1,
283                causes: vec![key],
284            });
285            let id = i as u32 * 2 + 1;
286            t.records.push(Record::Span(Span {
287                track: Track::MAIN,
288                id: id + 1,
289                parent: id,
290                name: rows,
291                origin: Origin::Host,
292                start: at + 20,
293                dur: rows_us,
294                cpu: None,
295                node: 0,
296                cut: false,
297            }));
298            t.records.push(Record::Span(Span {
299                track: Track::MAIN,
300                id,
301                parent: 0,
302                name: build,
303                origin: Origin::Kui,
304                start: at + 10,
305                dur: build_us,
306                cpu: Some(build_us),
307                node: 0,
308                cut: false,
309            }));
310            t.records.push(Record::Counter {
311                t: at + 10 + build_us,
312                frame: i + 1,
313                name: laid,
314                value: 40,
315            });
316            t.records.push(Record::FrameEnd {
317                t: at + 10 + build_us,
318                frame: i + 1,
319                unchanged: Some(false),
320                nodes: 10,
321            });
322            t.records.push(Record::Present {
323                t: at + 12_000,
324                frame: i + 1,
325                render: 1_000,
326                wait: 500,
327            });
328        }
329        t
330    }
331
332    fn row<'a>(r: &'a Report, what: &str) -> (usize, &'a (String, f64, f64)) {
333        r.rows
334            .iter()
335            .enumerate()
336            .find(|(_, row)| row.0 == what)
337            .unwrap_or_else(|| panic!("no row {what}:\n{}", r.text()))
338    }
339
340    #[test]
341    fn identical_recordings_grow_nothing() {
342        let a = recording(20, 2_000, 600);
343        let r = diff(&a, &a.clone());
344        assert_eq!(r.worst_growth(), 0.0);
345        assert!(r.rows.iter().all(|(_, a, b)| a == b));
346        assert_eq!(r.rows.len(), r.units.len());
347    }
348
349    #[test]
350    fn a_span_that_doubles_is_the_worst_growth() {
351        let a = recording(20, 2_000, 600);
352        let b = recording(20, 2_000, 1_200);
353        let r = diff(&a, &b);
354        let (i, (_, before, after)) = row(&r, "span rows [host] µs/frame");
355        assert_eq!((*before, *after), (600.0, 1_200.0));
356        assert!((r.growth(i).unwrap() - 1.0).abs() < 1e-9);
357        assert!(r.worst_growth() > 0.9, "{}", r.text());
358        let text = r.text();
359        let line = text
360            .lines()
361            .find(|l| l.starts_with("span rows [host] µs/frame"))
362            .unwrap();
363        assert!(line.ends_with("+100.0% ▲"), "{line}");
364        // Matched by text: the same names given other ids still match.
365        let mut c = recording(20, 2_000, 600);
366        c.names = crate::Names::new();
367        for n in ["pad", "key", "build", "rows", "laid"] {
368            c.names.get(n);
369        }
370        for r in &mut c.records {
371            match r {
372                Record::Span(s) => s.name += 1,
373                Record::FrameBegin { causes, .. } => causes.iter_mut().for_each(|c| *c += 1),
374                Record::Counter { name, .. } => *name += 1,
375                _ => {}
376            }
377        }
378        assert_eq!(diff(&a, &c).worst_growth(), 0.0, "{}", diff(&a, &c).text());
379    }
380
381    #[test]
382    fn a_tiny_time_and_a_maximum_do_not_count() {
383        // 10 µs → 40 µs is +300%, and below the noise floor.
384        let a = recording(20, 2_000, 10);
385        let b = recording(20, 2_000, 40);
386        let r = diff(&a, &b);
387        let (i, _) = row(&r, "span rows [host] µs/frame");
388        assert_eq!(r.growth(i), None);
389        let (i, _) = row(&r, "span rows [host] worst");
390        assert_eq!(r.unit(i), Unit::UsShown);
391        assert!(r.worst_growth() < 0.01, "{}", r.text());
392    }
393
394    #[test]
395    fn a_span_only_after_is_new() {
396        let a = recording(5, 2_000, 600);
397        let mut b = a.clone();
398        let (fill, _) = b.names.get("fill tabs");
399        b.records.push(Record::Span(Span {
400            track: Track::MAIN,
401            id: 999,
402            parent: 0,
403            name: fill,
404            origin: Origin::Kui,
405            start: 100,
406            dur: 300,
407            cpu: None,
408            node: 0,
409            cut: false,
410        }));
411        let r = diff(&a, &b);
412        let (_, row) = row(&r, "span fill tabs [kui] µs/frame");
413        assert_eq!((row.1, row.2), (0.0, 60.0));
414        assert!(r.text().contains("new"));
415    }
416}
kui_trace/diff.rs

kui_trace/
diff.rs
