perf(ui): give WOW_UI_VERBS a live window, so the instrument exists in a session

`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=<secs>` 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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn

crates/benilla-ui/src/script/tick.rs

@@ -263,6 +263,9 @@ impl super::UiScript {
         self.report_handler_profile(elapsed);
         // `WOW_UI_RAISES=<secs>`: beside it, and for the same window.
         self.report_raise_profile(elapsed);
+        // `WOW_UI_VERBS=<secs>`: 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=<secs>`: 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);

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=<secs>` prints a window every `<secs>` 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=<secs>`; `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<f32> = std::sync::OnceLock::new();
+    *SECS.get_or_init(|| {
+        std::env::var("WOW_UI_VERBS")
+            .ok()
+            .and_then(|v| v.trim().parse::<f32>().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<Option<Counts>> = 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<VerbRow> {
+    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<String, (u64, u128)>;
+
+/// `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<VerbRow> {
+    let mut out: Vec<VerbRow> = 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
+        );
+    }
+}