From 5764837e35c5eb60dbf4c7282471ba20efaf6d4a Mon Sep 17 00:00:00 2001 From: grom Date: Mon, 19 Oct 2026 20:35:07 -0600 Subject: [PATCH] perf(ui): give WOW_UI_VERBS a live window, so the instrument exists in a session MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `verb_prof` wrapped every global and every widget method and charged each call two `Instant::now`s — and the only caller of `log_report` was the `addon_harness` **example**'s `--together` load. Armed in the client it paid for every binding call and printed nothing at all. The one question it answers — which binding a handler's self time went into — is exactly the open one: `WOW_UI_HANDLERS` names `UIParent:OnUpdate` at 503 us/f in combat against 48 idle, and stops there. So `WOW_UI_VERBS=` now prints a window from `report_window`, called at the end of `UiScript::tick` beside the handler and raise reports, one level down from them. The bare `=1` the harnesses already pass reads as one second, which is why `period()` parses the same variable rather than taking a new one. A window is a **delta** against a snapshot (`PREV`), not a `reset`: `ROWS` is the one table and `log_report`'s callers read it whole at a moment of their own choosing — `--together` ticks ten times before printing its load bill, so a window that cleared the table would have handed it whatever happened after the last window instead of the load. The arithmetic is `diff`, split out and tested on its own because `window_delta` reads two process-wide statics and `diff` is the whole of the logic. It earns its keep immediately. `tick_bench` over the player's real 94-addon folder, 121-frame windows: `frame:GetLeft` costs **0.42 us/call** on a settled layout and **29.95 us/call** the moment anything moved — the same two calls a frame, 55% of the frame's whole verb bill — because the four edge getters call `settle()` and a resolve past tier 1 walks every live frame. During the load burst the same call is **370 us**. `GetWidth`/`GetHeight` already carry an authored-span shortcut for precisely this; the edge getters never got one. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-ui/src/script/tick.rs | 3 + crates/benilla-ui/src/script/verb_prof.rs | 160 ++++++++++++++++++++++ 2 files changed, 163 insertions(+) diff --git a/crates/benilla-ui/src/script/tick.rs b/crates/benilla-ui/src/script/tick.rs index 520307f3..87a37d1d 100644 --- a/crates/benilla-ui/src/script/tick.rs +++ b/crates/benilla-ui/src/script/tick.rs @@ -263,6 +263,9 @@ impl super::UiScript { self.report_handler_profile(elapsed); // `WOW_UI_RAISES=`: beside it, and for the same window. self.report_raise_profile(elapsed); + // `WOW_UI_VERBS=`: the same window one level down — which binding the handlers above + // spent their self time inside. + super::verb_prof::report_window(elapsed); // `WOW_UI_TICK=`: this tick's phases fold in before the report, so the row the // report prints includes the tick that triggered it. split.mark(Phase::Reports); diff --git a/crates/benilla-ui/src/script/verb_prof.rs b/crates/benilla-ui/src/script/verb_prof.rs index c048570c..8a61bee8 100644 --- a/crates/benilla-ui/src/script/verb_prof.rs +++ b/crates/benilla-ui/src/script/verb_prof.rs @@ -13,6 +13,13 @@ //! calls back into Lua (a handler fired from inside `Show`) has that nested time inside its own, //! as the handler profiler's *total* column does; the two instruments read against each other. //! +//! **Reading it live.** `WOW_UI_VERBS=` prints a window every `` from +//! [`report_window`], called at the end of [`UiScript::tick`](super::UiScript::tick) beside the +//! handler and raise reports, so a real session names its own verbs. That route is why the bare +//! `WOW_UI_VERBS=1` the harnesses pass now also means "one second": before it, the only caller of +//! [`log_report`] was the `addon_harness` example's `--together` load, and the profiler armed in +//! the client paid for every call and printed nothing at all. +//! //! Off, nothing is wrapped and nothing is paid. On, each call costs two `Instant::now`s and an //! uncontended lock, which is why this is an instrument and not a counter that ships armed. @@ -38,6 +45,124 @@ pub fn armed() -> bool { }) } +/// The report period from `WOW_UI_VERBS=`; `0.0` records without ever printing a window, +/// for a caller that prints [`log_report`] on its own schedule. Read once. +fn period() -> f32 { + static SECS: std::sync::OnceLock = std::sync::OnceLock::new(); + *SECS.get_or_init(|| { + std::env::var("WOW_UI_VERBS") + .ok() + .and_then(|v| v.trim().parse::().ok()) + .filter(|s| s.is_finite() && *s > 0.0) + .unwrap_or(0.0) + }) +} + +/// Rows a window prints before rolling the rest into a `… N more` line. +const REPORT_ROWS: usize = 16; + +/// Wall seconds and frames since the last window, beside [`ROWS`]: process-wide for the same +/// reason the rows are, so a harness holding several VMs still reads one window. +static WINDOW: Mutex<(f32, u32)> = Mutex::new((0.0, 0)); + +/// [`ROWS`] as the previous window left it, so a window can be a **delta**. +/// +/// It would be shorter to [`reset`] after printing, and wrong: [`ROWS`] is the one table and +/// [`log_report`]'s callers read it whole, at a moment of their own choosing. The `addon_harness` +/// example's `--together` ticks ten times before printing its load bill, so a window that cleared +/// the table would hand it whatever happened after the last window instead of the load. A snapshot +/// costs one clone of a few hundred rows a second and leaves the cumulative table alone. +static PREV: Mutex> = Mutex::new(None); + +/// Count a ticked frame and print the window when it is due, then start a fresh one. +pub(super) fn report_window(elapsed: f32) { + if !armed() || period() <= 0.0 { + return; + } + let (window, frames) = { + let mut w = WINDOW.lock().unwrap_or_else(|p| p.into_inner()); + w.0 += elapsed; + w.1 += 1; + if w.0 < period() { + return; + } + std::mem::replace(&mut *w, (0.0, 0)) + }; + // What this window did, not what the process has done: a cumulative table hides a verb whose + // whole cost arrived in one burst three minutes ago. + log_window(&window_delta(), window, frames); +} + +/// Every verb's cost **since the last window**, costliest first, and bank the new baseline. +fn window_delta() -> Vec { + let now: Counts = ROWS + .lock() + .unwrap_or_else(|p| p.into_inner()) + .as_ref() + .cloned() + .unwrap_or_default(); + let mut prev = PREV.lock().unwrap_or_else(|p| p.into_inner()); + let rows = diff(&now, prev.as_ref()); + *prev = Some(now); + rows +} + +/// `(calls, nanos)` per verb name, the shape [`ROWS`] and [`PREV`] both hold. +type Counts = HashMap; + +/// `now - was` per verb, costliest first; a verb with no calls this window is left out. +/// +/// Split out from [`window_delta`] because that one reads two process-wide statics and this is the +/// whole of the arithmetic. +fn diff(now: &Counts, was: Option<&Counts>) -> Vec { + let mut out: Vec = now + .iter() + .filter_map(|(name, &(calls, nanos))| { + let (p_calls, p_nanos) = was.and_then(|w| w.get(name)).copied().unwrap_or_default(); + // Saturating for its own sake: the totals only ever grow, so the subtraction cannot + // underflow, and an `unwrap`-free arithmetic is one fewer thing to be wrong about. + let calls = calls.saturating_sub(p_calls); + (calls > 0).then(|| VerbRow { + name: name.clone(), + calls, + micros: nanos.saturating_sub(p_nanos) as f64 / 1000.0, + }) + }) + .collect(); + out.sort_by(|a, b| b.micros.total_cmp(&a.micros).then(a.name.cmp(&b.name))); + out +} + +/// The `[ui-verbs]` window block, per frame as the client's other cost reports are. +fn log_window(rows: &[VerbRow], window: f32, frames: u32) { + let f = f64::from(frames.max(1)); + let total: f64 = rows.iter().map(|r| r.micros).sum(); + let calls: f64 = rows.iter().map(|r| r.calls as f64).sum(); + eprintln!( + "[ui-verbs] {window:.2}s · {frames} frames · {} verbs · self {:.0} us/f over {calls_pf:.0} calls/f", + rows.len(), + total / f, + calls_pf = calls / f, + ); + eprintln!("[ui-verbs] us/f calls/f us/call verb"); + for r in rows.iter().take(REPORT_ROWS) { + eprintln!( + "[ui-verbs] {:6.1} {:8.1} {:8.2} {}", + r.micros / f, + r.calls as f64 / f, + r.micros / r.calls.max(1) as f64, + r.name + ); + } + if let Some(rest) = rows.len().checked_sub(REPORT_ROWS).filter(|n| *n > 0) { + let tail: f64 = rows.iter().skip(REPORT_ROWS).map(|r| r.micros).sum(); + eprintln!( + "[ui-verbs] {:6.1} … {rest} more", + tail / f + ); + } +} + fn record(name: &str, nanos: u128) { let mut rows = ROWS.lock().unwrap_or_else(|p| p.into_inner()); let rows = rows.get_or_insert_with(HashMap::new); @@ -159,3 +284,38 @@ pub(super) fn install(lua: &Lua) -> mlua::Result<()> { eprintln!("[ui-verbs] armed — {n} verbs timed (WOW_UI_VERBS)"); Ok(()) } + +#[cfg(test)] +mod tests { + use super::{diff, Counts}; + + fn counts(rows: &[(&str, u64, u128)]) -> Counts { + rows.iter() + .map(|&(n, c, ns)| (n.to_string(), (c, ns))) + .collect() + } + + #[test] + fn a_window_reports_its_own_calls_and_not_the_process_total() { + let first = counts(&[("CreateFrame", 10, 10_000), ("frame:Show", 4, 2_000)]); + let rows = diff(&first, None); + assert_eq!(rows.len(), 2, "no baseline: everything is this window's"); + assert_eq!(rows[0].name, "CreateFrame", "costliest first"); + assert_eq!((rows[0].calls, rows[0].micros), (10, 10.0)); + + // CreateFrame was not called again; frame:Show was, three times for 1 us. + let second = counts(&[("CreateFrame", 10, 10_000), ("frame:Show", 7, 3_000)]); + let rows = diff(&second, Some(&first)); + assert_eq!( + rows.len(), + 1, + "a verb with no calls this window is left out" + ); + assert_eq!((rows[0].name.as_str(), rows[0].calls), ("frame:Show", 3)); + assert!( + (rows[0].micros - 1.0).abs() < 1e-9, + "1000 ns of new cost, not the 3000 it has ever cost: {}", + rows[0].micros + ); + } +}