Retain opt-in layout performance diagnostics

core/src/layout_diagnostics.rs

@@ -0,0 +1,331 @@
+//! Opt-in counters and coarse timers for explaining CPU layout cost.
+//!
+//! Enable the `layout-diagnostics` feature. With it disabled, none of the
+//! instrumentation is compiled into Iris. The retained rig in
+//! `tests/layout_diagnostics.rs` is the ordinary entry point.
+//!
+//! Timers are inclusive: `update total` contains `full layout` or
+//! `incremental layout`, and `text render` contains shaping and glyph
+//! placement. They locate cost within one instrumented run and must not be
+//! added together. Use an uninstrumented build under `perf` for final CPU
+//! totals; counting every primitive and distinct widget deliberately perturbs
+//! the instrumented run.
+
+use crate::WidgetId;
+use std::{
+    cell::RefCell,
+    collections::{HashMap, HashSet},
+    fmt::Write,
+    time::Instant,
+};
+
+#[derive(Clone, Copy)]
+pub(crate) enum Counter {
+    Updates,
+    ResizeDependents,
+    DrawRequests,
+    WidgetDraws,
+    PlaceCalls,
+    SizeReads,
+    HintHits,
+    HintMisses,
+    ReuseAttempts,
+    ReuseExact,
+    ReuseMoved,
+    ReuseDirty,
+    ReuseWrongParent,
+    ReuseUnslotted,
+    ReuseOwnResize,
+    ReuseDescendantResize,
+    ResizeChecks,
+    ResizeCheckChildren,
+    QueuePops,
+    DepthSteps,
+    EagerReaderRedraws,
+    LocalRedraws,
+    SizeChanges,
+    ReaderEdges,
+    PrimitiveWrites,
+    TextRenders,
+    TextShapeHits,
+    TextShapes,
+}
+
+impl Counter {
+    const COUNT: usize = Self::TextShapes as usize + 1;
+
+    const NAMES: [&'static str; Self::COUNT] = [
+        "updates",
+        "resize dependents",
+        "draw requests",
+        "widget draws",
+        "place calls",
+        "draw-result size reads",
+        "hint hits",
+        "hint misses",
+        "reuse attempts",
+        "reuse exact",
+        "reuse moved",
+        "reuse: dirty",
+        "reuse: wrong parent",
+        "reuse: unslotted",
+        "reuse: own resize",
+        "reuse: descendant resize",
+        "resize checks",
+        "resize children checked",
+        "redraw queue pops",
+        "depth steps",
+        "eager reader redraws",
+        "local redraws",
+        "size changes",
+        "reader edges",
+        "primitive writes",
+        "text renders",
+        "text shape hits",
+        "text shapes",
+    ];
+}
+
+#[derive(Clone, Copy)]
+pub(crate) enum TimerKind {
+    Update,
+    FullLayout,
+    ResizeMarking,
+    IncrementalLayout,
+    TextRender,
+    TextShape,
+    GlyphPlacement,
+}
+
+impl TimerKind {
+    const COUNT: usize = Self::GlyphPlacement as usize + 1;
+
+    const NAMES: [&'static str; Self::COUNT] = [
+        "update total",
+        "full layout",
+        "resize marking",
+        "incremental layout",
+        "text render",
+        "text shape",
+        "glyph placement",
+    ];
+}
+
+#[derive(Clone)]
+pub struct Report {
+    counters: [u64; Counter::COUNT],
+    nanos: [u64; TimerKind::COUNT],
+    distinct_widgets: usize,
+    distinct_text_widgets: usize,
+    hot_widgets: Vec<Callsite>,
+    hot_text: Vec<Callsite>,
+}
+
+impl Default for Report {
+    fn default() -> Self {
+        Self {
+            counters: [0; Counter::COUNT],
+            nanos: [0; TimerKind::COUNT],
+            distinct_widgets: 0,
+            distinct_text_widgets: 0,
+            hot_widgets: Vec::new(),
+            hot_text: Vec::new(),
+        }
+    }
+}
+
+impl Report {
+    pub fn counters(&self) -> impl Iterator<Item = (&'static str, u64)> + '_ {
+        Counter::NAMES.into_iter().zip(self.counters)
+    }
+
+    /// Inclusive elapsed time accumulated for each targeted operation.
+    pub fn timings_ns(&self) -> impl Iterator<Item = (&'static str, u64)> + '_ {
+        TimerKind::NAMES.into_iter().zip(self.nanos)
+    }
+
+    pub fn distinct_widgets(&self) -> usize {
+        self.distinct_widgets
+    }
+
+    pub fn distinct_text_widgets(&self) -> usize {
+        self.distinct_text_widgets
+    }
+
+    pub fn hot_widgets(&self) -> &[Callsite] {
+        &self.hot_widgets
+    }
+
+    pub fn hot_text(&self) -> &[Callsite] {
+        &self.hot_text
+    }
+
+    /// Formats nonzero totals divided by `frames`.
+    pub fn per_frame(&self, frames: usize) -> String {
+        let divisor = frames.max(1) as f64;
+        let mut out = String::new();
+        for (name, value) in self.counters() {
+            if value != 0 {
+                let _ = writeln!(out, "  {name:<27} {:>12.2}", value as f64 / divisor);
+            }
+        }
+        if self.distinct_widgets != 0 {
+            let _ = writeln!(
+                out,
+                "  {:<27} {:>12}",
+                "distinct widgets", self.distinct_widgets
+            );
+        }
+        if self.distinct_text_widgets != 0 {
+            let _ = writeln!(
+                out,
+                "  {:<27} {:>12}",
+                "distinct text widgets", self.distinct_text_widgets
+            );
+        }
+        for (name, nanos) in self.timings_ns() {
+            if nanos != 0 {
+                let ms = nanos as f64 / divisor / 1_000_000.0;
+                let _ = writeln!(out, "  {name:<27} {ms:>12.3} ms");
+            }
+        }
+        if !self.hot_widgets.is_empty() {
+            let _ = writeln!(out, "  hottest widget draws:");
+            for callsite in &self.hot_widgets {
+                let calls = callsite.calls as f64 / divisor;
+                let _ = writeln!(
+                    out,
+                    "    {calls:>9.2}  {:?} {}",
+                    callsite.id, callsite.label
+                );
+            }
+        }
+        if !self.hot_text.is_empty() {
+            let _ = writeln!(out, "  hottest text renders:");
+            for callsite in &self.hot_text {
+                let calls = callsite.calls as f64 / divisor;
+                let _ = writeln!(
+                    out,
+                    "    {calls:>9.2}  {:>3} widths  {:?} {}",
+                    callsite.distinct_widths, callsite.id, callsite.label
+                );
+            }
+        }
+        out
+    }
+}
+
+#[derive(Clone)]
+pub struct Callsite {
+    pub id: WidgetId,
+    pub label: String,
+    pub calls: u64,
+    pub distinct_widths: usize,
+}
+
+#[derive(Default)]
+struct Calls {
+    label: String,
+    count: u64,
+    widths: HashSet<Option<u32>>,
+}
+
+#[derive(Default)]
+struct Current {
+    report: Report,
+    widgets: HashMap<WidgetId, Calls>,
+    text_widgets: HashMap<WidgetId, Calls>,
+}
+
+thread_local! {
+    static CURRENT: RefCell<Current> = RefCell::new(Current::default());
+}
+
+pub(crate) fn bump(counter: Counter) {
+    CURRENT.with_borrow_mut(|current| current.report.counters[counter as usize] += 1);
+}
+
+pub(crate) fn draw_widget(id: WidgetId, label: &str) {
+    CURRENT.with_borrow_mut(|current| {
+        let calls = current.widgets.entry(id).or_default();
+        if calls.label.is_empty() {
+            calls.label = label.to_owned();
+        }
+        calls.count += 1;
+    });
+}
+
+pub(crate) fn render_text(id: WidgetId, label: &str, width: Option<f32>) {
+    CURRENT.with_borrow_mut(|current| {
+        let calls = current.text_widgets.entry(id).or_default();
+        if calls.label.is_empty() {
+            calls.label = label.to_owned();
+        }
+        calls.count += 1;
+        calls.widths.insert(width.map(f32::to_bits));
+    });
+}
+
+pub(crate) struct Timer {
+    kind: TimerKind,
+    start: Instant,
+}
+
+pub(crate) fn timer(kind: TimerKind) -> Timer {
+    Timer {
+        kind,
+        start: Instant::now(),
+    }
+}
+
+impl Drop for Timer {
+    fn drop(&mut self) {
+        let nanos = self.start.elapsed().as_nanos().min(u64::MAX as u128) as u64;
+        CURRENT.with_borrow_mut(|current| current.report.nanos[self.kind as usize] += nanos);
+    }
+}
+
+/// Takes all diagnostics accumulated on this thread and resets them.
+pub fn take() -> Report {
+    CURRENT.with_borrow_mut(|current| {
+        current.report.distinct_widgets = current.widgets.len();
+        current.report.distinct_text_widgets = current.text_widgets.len();
+        current.report.hot_widgets = hottest(&current.widgets);
+        current.report.hot_text = hottest(&current.text_widgets);
+        let report = std::mem::take(&mut current.report);
+        current.widgets.clear();
+        current.text_widgets.clear();
+        report
+    })
+}
+
+fn hottest(calls: &HashMap<WidgetId, Calls>) -> Vec<Callsite> {
+    let mut calls: Vec<_> = calls
+        .iter()
+        .map(|(&id, calls)| Callsite {
+            id,
+            label: calls.label.clone(),
+            calls: calls.count,
+            distinct_widths: calls.widths.len(),
+        })
+        .collect();
+    calls.sort_by(|a, b| b.calls.cmp(&a.calls).then_with(|| a.label.cmp(&b.label)));
+    calls.truncate(8);
+    calls
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn taking_a_report_resets_its_counters() {
+        let _ = take();
+        bump(Counter::Updates);
+        bump(Counter::Updates);
+
+        let report = take();
+        assert_eq!(report.counters().next(), Some(("updates", 2)));
+        assert!(take().counters().all(|(_, count)| count == 0));
+    }
+}