ui: WOW_UI_PHASES — the UI pass's phase split, windowed

`WOW_UI_TICK` measures `UiScript::tick`. `[sys-timing]` measures the Bevy system around it,
`ui_script::extract::tick_script`, which also runs the FontString measure round-trip and
`UiScript::resolve`. In a combat session the first read 38 ms/s — its lowest of the whole run —
while the second read 157 ms/s. Neither instrument was wrong, and 76% of the cost was in the space
between them, which is where the stutter players report lives.

`UiFrameCost` has carried the whole split since the hover recorder needed it, and `WOW_UI_COST=1`
prints it one line per frame: at this client's framerate, twenty thousand synchronous stderr writes
a minute from the thread being measured, which is the trap `sys_timing`'s header records costing
15 ms a frame. The split existed and was unusable in exactly the situation it was for.

So a window, and a worst column — a phase that is ruinous on one frame in a hundred has a mean near
nothing and is the only thing a player feels. `derives` is in the per-frame line because
`UiFrameCost::derives` is documented "expected zero", so a nonzero one names a whole-graph
re-derivation on sight.

`UiFrameCost::stamped` comes with it: the paint can return before any of its three arms wrote this
frame's phases, and a reader that cannot tell counts the previous frame twice.

Armed in ./measure.sh at 5 s, with the per-frame form left alone for the hover recorder.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn

crates/benilla-app/src/hover_log.rs

@@ -363,6 +363,9 @@ fn parse_row(line: &str) -> Option<Row> {
             skipped: num(11)? != 0.0,
             spliced: fields.get(17).and_then(|f| f.parse().ok()).unwrap_or(0),
             dropped: fields.get(25).and_then(|f| f.parse().ok()).unwrap_or(0),
+            // A row that was written is a frame the paint wrote; the recorder has no column for
+            // it because it only ever records stamped frames.
+            stamped: true,
         },
         mesh,
         tip: if owner.is_empty() {

crates/benilla-app/src/ui_script/cost_report.rs

@@ -0,0 +1,342 @@
+//! `WOW_UI_PHASES=<secs>`: the UI pass's phase split, windowed.
+//!
+//! [`super::UiFrameCost`] has carried the whole split — tick, resolve, measure, extract, convert,
+//! diff — since the hover recorder needed it, and `WOW_UI_COST=1` prints it one line a frame. That
+//! line cannot be used on a live session: at the framerate this client runs, it is twenty thousand
+//! synchronous stderr writes a minute from the thread being measured, which is the trap
+//! `benilla_world::sys_timing`'s header records costing 15 ms a frame. So the split existed and was
+//! unreadable in exactly the situation it was for.
+//!
+//! What this is for, concretely. `WOW_UI_TICK` splits [`benilla_ui::script::UiScript::tick`] — the
+//! Lua handlers — and reports 0.4–0.7 ms a frame in play. But the Bevy system around it,
+//! `ui_script::extract::tick_script`, also runs the FontString measure round-trip and
+//! `UiScript::resolve`, and `[sys-timing]` measured *that* at 11.7 ms a run for half a second at a
+//! time, recurring every few seconds, in a session whose handler profile was clean. Everything
+//! between those two numbers was unattributed: the tick instrument could not see it and the
+//! per-system instrument could not look inside it. Hence a window, hence the worst column — a
+//! stall that recurs every ten seconds has a mean near nothing and is the only thing a player
+//! feels.
+//!
+//! One `Last` system reading two resources; nothing on the hot path, and nothing at all unarmed.
+
+use std::time::Instant;
+
+use bevy::prelude::*;
+
+use super::{UiCostWanted, UiFrameCost};
+use crate::ui_pass::UiMeshCost;
+
+/// The window in seconds, or `None` unarmed. `WOW_UI_PHASES=5` is the useful shape; bare
+/// `WOW_UI_PHASES=1` reads as one second, not as a flag, so it matches `WOW_UI_TICK` and
+/// `WOW_UI_HANDLERS` rather than `WOW_UI_COST`'s per-frame `=1`.
+fn window_secs() -> Option<f64> {
+    static ON: std::sync::OnceLock<Option<f64>> = std::sync::OnceLock::new();
+    *ON.get_or_init(|| {
+        std::env::var("WOW_UI_PHASES")
+            .ok()
+            .and_then(|v| v.trim().parse::<f64>().ok())
+            .filter(|s| *s > 0.0)
+    })
+}
+
+/// The phases in the order a frame runs them, each with what it actually covers. The labels are
+/// the point: `resolve` is not only `UiScript::resolve`, and a reader who assumes it is looks for
+/// the cost in the layout solver when it is in the font engine.
+const PHASES: [(&str, &str); 7] = [
+    ("tick", "the Lua handlers — WOW_UI_TICK splits this one"),
+    ("resolve", "FontString measures + the layout resolve"),
+    ("measure", "message-line row counts"),
+    ("extract", "the VM's walk into extracted entries"),
+    ("convert", "entries into screen quads (or the splice)"),
+    ("diff", "the changed-quad search"),
+    ("mesh", "sort, clip, split and the mesh writes"),
+];
+
+/// One window's samples. Per-frame μs is kept rather than reduced so the window can answer for a
+/// percentile and a worst frame, which a running mean cannot.
+#[derive(Resource)]
+struct Window {
+    at: Instant,
+    secs: f64,
+    /// `[phase][frame]`, μs.
+    us: [Vec<u32>; PHASES.len()],
+    /// Every frame's whole-pass μs, and the costliest frame's own split.
+    totals: Vec<u32>,
+    worst: [u32; PHASES.len()],
+    measured: u64,
+    solves: u64,
+    derives: u64,
+    quads: u64,
+    spliced: u64,
+    dropped: u64,
+    mesh_runs: u64,
+    mesh_rewrites: u64,
+}
+
+impl Window {
+    fn new(secs: f64) -> Self {
+        Self {
+            at: Instant::now(),
+            secs,
+            us: std::array::from_fn(|_| Vec::new()),
+            totals: Vec::new(),
+            worst: [0; PHASES.len()],
+            measured: 0,
+            solves: 0,
+            derives: 0,
+            quads: 0,
+            spliced: 0,
+            dropped: 0,
+            mesh_runs: 0,
+            mesh_rewrites: 0,
+        }
+    }
+
+    fn clear(&mut self) {
+        self.at = Instant::now();
+        for v in &mut self.us {
+            v.clear();
+        }
+        self.totals.clear();
+        self.worst = [0; PHASES.len()];
+        self.measured = 0;
+        self.solves = 0;
+        self.derives = 0;
+        self.quads = 0;
+        self.spliced = 0;
+        self.dropped = 0;
+        self.mesh_runs = 0;
+        self.mesh_rewrites = 0;
+    }
+}
+
+/// The `WOW_UI_PHASES` report. Nothing is registered unless the variable is set, so the whole
+/// module costs one `OnceLock` read at startup otherwise.
+pub(super) fn plugin(app: &mut App) {
+    let Some(secs) = window_secs() else {
+        return;
+    };
+    // `init_resource` first, so this holds whichever plugin builds first (as `hover_log` does).
+    app.init_resource::<UiCostWanted>();
+    app.world_mut().resource_mut::<UiCostWanted>().0 = true;
+    app.insert_resource(Window::new(secs));
+    app.add_systems(Last, report);
+    eprintln!("[ui-phases] armed — the UI pass's phase split every {secs:.1}s (WOW_UI_PHASES)");
+}
+
+/// A counter's per-frame rate.
+#[allow(clippy::cast_precision_loss)]
+fn rate(total: u64, frames: f64) -> f64 {
+    total as f64 / frames
+}
+
+/// μs at the given fraction of the sorted samples; 0 on an empty window.
+fn pct(sorted: &[u32], q: f64) -> f64 {
+    if sorted.is_empty() {
+        return 0.0;
+    }
+    #[allow(clippy::cast_possible_truncation, clippy::cast_sign_loss)]
+    let i = ((sorted.len() - 1) as f64 * q).round() as usize;
+    f64::from(sorted[i])
+}
+
+/// One phase's row, μs.
+struct Row {
+    phase: &'static str,
+    covers: &'static str,
+    mean: f64,
+    p99: f64,
+    worst: f64,
+}
+
+/// What a window has to say, separated from saying it so a test can read it. Pure: every number
+/// here comes from the samples and nothing else.
+struct Summary {
+    frames: usize,
+    /// Mean whole-pass ms a frame.
+    whole_ms: f64,
+    /// The costliest frame's whole-pass ms, and the phase most of it was in.
+    worst_ms: f64,
+    mostly: &'static str,
+    /// Costliest first, as every other report in this project ranks: the question a reader brings
+    /// is which phase to look at.
+    rows: Vec<Row>,
+}
+
+fn summarize(win: &Window) -> Summary {
+    #[allow(clippy::cast_precision_loss)]
+    let per = win.totals.len() as f64;
+    let mut rows: Vec<Row> = PHASES
+        .iter()
+        .enumerate()
+        .map(|(i, (phase, covers))| {
+            let mut sorted = win.us[i].clone();
+            sorted.sort_unstable();
+            Row {
+                phase,
+                covers,
+                mean: sorted.iter().map(|&u| f64::from(u)).sum::<f64>() / per,
+                p99: pct(&sorted, 0.99),
+                worst: pct(&sorted, 1.0),
+            }
+        })
+        .collect();
+    rows.sort_by(|a, b| b.mean.total_cmp(&a.mean));
+    Summary {
+        frames: win.totals.len(),
+        whole_ms: win.totals.iter().map(|&t| f64::from(t)).sum::<f64>() / per / 1000.0,
+        worst_ms: f64::from(win.worst.iter().sum::<u32>()) / 1000.0,
+        mostly: win
+            .worst
+            .iter()
+            .enumerate()
+            .max_by_key(|(_, us)| **us)
+            .map_or("nothing", |(i, _)| PHASES[i].0),
+        rows,
+    }
+}
+
+/// `Option<Res<_>>` for the mesh cost: it belongs to `ui_pass`, and an instrument must not be the
+/// reason a configuration that builds one plugin without the other fails to start. Absent, the
+/// mesh row reads zero, which is also what it reads on a frame that rebuilt nothing.
+fn report(cost: Res<UiFrameCost>, mesh: Option<Res<UiMeshCost>>, mut win: ResMut<Window>) {
+    let mesh = mesh.map(|m| (m.rebuilt, m.total, m.runs, m.rewrites));
+    let (mesh_rebuilt, mesh_total, mesh_runs, mesh_rewrites) = mesh.unwrap_or((false, 0, 0, 0));
+    // `stamped` and not `pass.live`: the pass can be live and still return before the paint wrote
+    // this frame's split, and the previous frame's numbers counted twice are worse than a frame
+    // not counted at all.
+    if cost.stamped {
+        #[allow(clippy::cast_possible_truncation)]
+        let frame = [
+            cost.tick as u32,
+            cost.resolve as u32,
+            cost.measure as u32,
+            cost.extract as u32,
+            cost.convert as u32,
+            cost.diff as u32,
+            // A frame that rebuilt no mesh spent nothing in it, which is a real zero, not a gap.
+            if mesh_rebuilt { mesh_total as u32 } else { 0 },
+        ];
+        let total: u32 = frame.iter().sum();
+        if total >= win.totals.iter().copied().max().unwrap_or(0) {
+            win.worst = frame;
+        }
+        for (i, us) in frame.iter().enumerate() {
+            win.us[i].push(*us);
+        }
+        win.totals.push(total);
+        win.measured += cost.measured as u64;
+        win.solves += cost.solves;
+        win.derives += cost.derives;
+        win.quads += cost.quads as u64;
+        win.spliced += cost.spliced as u64;
+        win.dropped += cost.dropped as u64;
+        win.mesh_runs += mesh_runs as u64;
+        win.mesh_rewrites += mesh_rewrites as u64;
+    }
+    let elapsed = win.at.elapsed().as_secs_f64();
+    if elapsed < win.secs || win.totals.is_empty() {
+        // An idle window prints nothing rather than a row of zeroes; the clock only restarts on a
+        // real report, so a stalled client's next window still covers the stall.
+        if elapsed >= win.secs {
+            win.at = Instant::now();
+        }
+        return;
+    }
+    let s = summarize(&win);
+    eprintln!(
+        "[ui-phases] {elapsed:.2}s · {} frames · {:.3} ms/f over the whole pass · \
+         worst frame {:.1} ms (mostly {})",
+        s.frames, s.whole_ms, s.worst_ms, s.mostly,
+    );
+    eprintln!("[ui-phases]   mean/f      p99    worst  phase");
+    for r in &s.rows {
+        eprintln!(
+            "[ui-phases] {:8.1} {:8.1} {:8.0}  {:<9} — {}",
+            r.mean, r.p99, r.worst, r.phase, r.covers,
+        );
+    }
+    #[allow(clippy::cast_precision_loss)]
+    let per = win.totals.len() as f64;
+    eprintln!(
+        "[ui-phases] per frame: {:.2} measured · {:.2} solves · {:.3} derives · \
+         {:.0} quads · {:.2} spliced · {:.2} dropped · mesh {:.2} runs, {:.2} rewrites",
+        rate(win.measured, per),
+        rate(win.solves, per),
+        rate(win.derives, per),
+        rate(win.quads, per),
+        rate(win.spliced, per),
+        rate(win.dropped, per),
+        rate(win.mesh_runs, per),
+        rate(win.mesh_rewrites, per),
+    );
+    win.clear();
+}
+
+#[cfg(test)]
+mod tests {
+    use super::{summarize, Window, PHASES};
+
+    /// Relations, never durations: the samples are made up, so only the shape is asserted.
+    fn window(frames: &[[u32; PHASES.len()]]) -> Window {
+        let mut w = Window::new(5.0);
+        for frame in frames {
+            let total: u32 = frame.iter().sum();
+            if total >= w.totals.iter().copied().max().unwrap_or(0) {
+                w.worst = *frame;
+            }
+            for (i, us) in frame.iter().enumerate() {
+                w.us[i].push(*us);
+            }
+            w.totals.push(total);
+        }
+        w
+    }
+
+    /// The reason this report has a worst column at all, and the shape the last play session had:
+    /// `resolve` is cheap on almost every frame and ruinous on a few, while `tick` costs a steady
+    /// amount on all of them. Ranked by the mean alone — which is how `[ui-tick]` reported the
+    /// same session — `tick` is the whole story and the stutter has no name.
+    #[test]
+    fn a_phase_that_spikes_outranks_a_steady_one_only_in_the_worst_column() {
+        // [tick, resolve, measure, extract, convert, diff, mesh]
+        let mut frames = vec![[400, 100, 0, 0, 0, 0, 0]; 99];
+        frames.push([400, 12_000, 0, 0, 0, 0, 0]);
+        let s = summarize(&window(&frames));
+        let tick = s.rows.iter().find(|r| r.phase == "tick").expect("a row");
+        let resolve = s.rows.iter().find(|r| r.phase == "resolve").expect("a row");
+        assert!(
+            tick.mean > resolve.mean,
+            "the steady phase should still own the mean ({} vs {})",
+            tick.mean,
+            resolve.mean
+        );
+        assert!(
+            resolve.worst > tick.worst * 10.0,
+            "the spiky phase's worst single frame should dwarf the steady one's ({} vs {})",
+            resolve.worst,
+            tick.worst
+        );
+        assert!(
+            resolve.p99 < resolve.worst,
+            "one frame in a hundred must not reach the p99 ({} vs {})",
+            resolve.p99,
+            resolve.worst
+        );
+        assert_eq!(
+            s.mostly, "resolve",
+            "the costliest frame was mostly the spike, whatever the means say"
+        );
+    }
+
+    /// The other half, so the test above cannot pass by the summary having stopped measuring: a
+    /// phase that is cheap on every frame reads as cheap in every column.
+    #[test]
+    fn a_phase_that_never_spikes_has_no_worst_to_show() {
+        let s = summarize(&window(&vec![[400, 100, 7, 0, 0, 0, 0]; 50]));
+        let measure = s.rows.iter().find(|r| r.phase == "measure").expect("a row");
+        assert!((measure.mean - 7.0).abs() < 0.001, "{}", measure.mean);
+        assert!((measure.worst - 7.0).abs() < 0.001, "{}", measure.worst);
+        assert_eq!(s.mostly, "tick", "the only phase with any weight");
+    }
+}

crates/benilla-app/src/ui_script/extract/mod.rs

@@ -483,6 +483,8 @@ pub(super) fn tick_script(
     // Per frame: both halves' measure passes add to these, and only this zeroes them.
     ui_cost.measured = 0;
     ui_cost.measured_texts.clear();
+    // The phases below are last frame's until the paint writes them; see `UiFrameCost::stamped`.
+    ui_cost.stamped = false;
     let mut t_mark = cost_on.then(std::time::Instant::now);
     // μs since the previous mark, re-armed; nothing with the meter off.
     let mut lap = move || -> u128 {
@@ -735,6 +737,7 @@ pub(super) fn paint_script(
                 skipped: true,
                 spliced: 0,
                 dropped: 0,
+                stamped: true,
             };
         }
         if printing {
@@ -958,6 +961,7 @@ pub(super) fn paint_script(
                 skipped: false,
                 spliced: changed.len(),
                 dropped: align.dropped.len(),
+                stamped: true,
             };
         }
         if printing {
@@ -1090,6 +1094,7 @@ pub(super) fn paint_script(
             skipped: false,
             spliced: 0,
             dropped: 0,
+            stamped: true,
         };
         if printing {
             eprintln!(

crates/benilla-app/src/ui_script/mod.rs

@@ -15,6 +15,7 @@ use benilla_world::schedule::WorldStage;
 pub(crate) mod addons;
 pub mod chunk_cache;
 mod content;
+mod cost_report;
 pub(crate) mod extract;
 mod flash_trace;
 mod input;
@@ -84,6 +85,10 @@ pub(crate) struct UiFrameCost {
     pub(crate) spliced: usize,
     /// Entries the splice dropped (drawn last frame, not now); `[ui-cost] dropped=` prints it.
     pub(crate) dropped: usize,
+    /// Whether the phases below belong to *this* frame: cleared by [`extract::tick_script`] and
+    /// set by whichever of [`extract::paint_script`]'s three arms wrote them. The paint can return
+    /// before any of them, and a reader that cannot tell counts the previous frame twice.
+    pub(crate) stamped: bool,
 }
 
 /// Whether [`UiFrameCost`] is wanted this run: `WOW_UI_COST=1` or the hover recorder.
@@ -277,6 +282,8 @@ impl Plugin for UiScriptPlugin {
         crate::shutdown::on_app_exit(app, shutdown_on_exit.into_configs());
         app.insert_resource(UiScaleCvar(default_ui_scale()))
             .init_resource::<UiFrameCost>()
+            // `WOW_UI_PHASES=<secs>`; nothing is registered unarmed.
+            .add_plugins(cost_report::plugin)
             .init_resource::<crate::bindings::WheelNotches>()
             .init_resource::<UiCostWanted>()
             .init_resource::<PointerOverUi>()

measure.sh

@@ -18,8 +18,14 @@ root="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
 # Per-system milliseconds once a second, and the stall watchdog that names a system still running
 # after WOW_STALL_MS. This is the one that says whether a frame went to the UI or the world.
 export WOW_SYSTEM_TIMING=1
+# The UI *pass*, split into its phases: tick, the FontString measure round-trip and layout
+# resolve, extract, convert, the mesh rebuild. The one that distinguishes "the addons are slow"
+# from "the layout is resolving a dirty graph", which the tick split below cannot see — the first
+# session with this armed found 11.7 ms a frame outside the tick in a run whose handler profile was
+# clean.
+export WOW_UI_PHASES=5
 # The UI tick, split into its eleven engine phases, with `C_Timer` fires credited to the line that
-# armed them.
+# armed them. Inside WOW_UI_PHASES' `tick` row.
 export WOW_UI_TICK=5
 # Per handler: self and total time, calls, and the worst single call — the column that names a
 # handler stalling one frame in five hundred, which no mean can show.
@@ -37,5 +43,5 @@ if [ "${1:-}" = "--stalls" ]; then
 fi
 
 echo "measure: armed —"
-env | grep -E '^WOW_(SYSTEM_TIMING|UI_TICK|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS)=' | sort | sed 's/^/  /'
+env | grep -E '^WOW_(SYSTEM_TIMING|UI_PHASES|UI_TICK|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS)=' | sort | sed 's/^/  /'
 exec "$root/run.sh" "$@"