From e4851df7df07b87ff95f3c9274e3aa089f65a67e Mon Sep 17 00:00:00 2001 From: grom Date: Tue, 20 Oct 2026 18:17:01 -0600 Subject: [PATCH] =?UTF-8?q?ui:=20WOW=5FUI=5FPHASES=20=E2=80=94=20the=20UI?= =?UTF-8?q?=20pass's=20phase=20split,=20windowed?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/hover_log.rs | 3 + .../benilla-app/src/ui_script/cost_report.rs | 342 ++++++++++++++++++ .../benilla-app/src/ui_script/extract/mod.rs | 5 + crates/benilla-app/src/ui_script/mod.rs | 7 + measure.sh | 10 +- 5 files changed, 365 insertions(+), 2 deletions(-) create mode 100644 crates/benilla-app/src/ui_script/cost_report.rs diff --git a/crates/benilla-app/src/hover_log.rs b/crates/benilla-app/src/hover_log.rs index 66133912..e53752ca 100644 --- a/crates/benilla-app/src/hover_log.rs +++ b/crates/benilla-app/src/hover_log.rs @@ -363,6 +363,9 @@ fn parse_row(line: &str) -> Option { 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() { diff --git a/crates/benilla-app/src/ui_script/cost_report.rs b/crates/benilla-app/src/ui_script/cost_report.rs new file mode 100644 index 00000000..1c929c77 --- /dev/null +++ b/crates/benilla-app/src/ui_script/cost_report.rs @@ -0,0 +1,342 @@ +//! `WOW_UI_PHASES=`: 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 { + static ON: std::sync::OnceLock> = std::sync::OnceLock::new(); + *ON.get_or_init(|| { + std::env::var("WOW_UI_PHASES") + .ok() + .and_then(|v| v.trim().parse::().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; PHASES.len()], + /// Every frame's whole-pass μs, and the costliest frame's own split. + totals: Vec, + 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::(); + app.world_mut().resource_mut::().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, +} + +fn summarize(win: &Window) -> Summary { + #[allow(clippy::cast_precision_loss)] + let per = win.totals.len() as f64; + let mut rows: Vec = 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::() / 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::() / per / 1000.0, + worst_ms: f64::from(win.worst.iter().sum::()) / 1000.0, + mostly: win + .worst + .iter() + .enumerate() + .max_by_key(|(_, us)| **us) + .map_or("nothing", |(i, _)| PHASES[i].0), + rows, + } +} + +/// `Option>` 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, mesh: Option>, mut win: ResMut) { + 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"); + } +} diff --git a/crates/benilla-app/src/ui_script/extract/mod.rs b/crates/benilla-app/src/ui_script/extract/mod.rs index 37d85e29..d5c0edef 100644 --- a/crates/benilla-app/src/ui_script/extract/mod.rs +++ b/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!( diff --git a/crates/benilla-app/src/ui_script/mod.rs b/crates/benilla-app/src/ui_script/mod.rs index 4b4ce980..02aa0601 100644 --- a/crates/benilla-app/src/ui_script/mod.rs +++ b/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::() + // `WOW_UI_PHASES=`; nothing is registered unarmed. + .add_plugins(cost_report::plugin) .init_resource::() .init_resource::() .init_resource::() diff --git a/measure.sh b/measure.sh index 08f497d8..0cf47334 100755 --- a/measure.sh +++ b/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" "$@"