perf(ui): the handler profiler names the worst single call, not only the mean

`WOW_UI_HANDLERS` ranked handlers by self time over the window, which is the
right ranking for what costs framerate and the wrong one for what costs a
frame. A handler that stalls once every four seconds has a mean near zero over
five hundred frames and never reaches the table at all.

The player's session had a 15-28 ms tick in nearly every five-second window —
one dropped frame every few seconds, which is the kind of thing a player
reports as "it hitches" and no average will ever show. The table said
`UIParent:OnUpdate 60.8 us/f` and nothing about it.

So each slot keeps its costliest single call, the table gets a `worst` column,
and the handlers whose worst call cost a frame are listed again underneath —
but only the ones the table left out, so the block says something new or
nothing. `tick_bench` prints the same ranking.

It names the stall on the first run, offline, in this interface:

```
15768.7 us once  (self 17080.8 us over 240 calls)  pfQuestMapTracker:OnUpdate
12339.4 us once  (self 13042.0 us over 240 calls)  AceEvent20Frame:OnUpdate
 5380.9 us once  (self 16166.0 us over 240 calls)  pfQuest\quest.lua:348:OnUpdate
```

92% of the tracker's whole cost over 240 frames is one call. Both of the top
two are steady per-frame allocators, which made the collector the first
suspect; the bench's own heap line refutes it — 222.8 MB live against 29.1
kB/frame of churn is ~131 s between 200%-pause cycles, not the ~4 s the stall
recurs on. What the per-binding bill says is in there instead: one `pcall` of
7.5 ms, and `frame:GetLeft` at 92 us a call, which is a layout resolve against
a dirty graph.

`measure.sh` comes with it. The set of instruments worth arming for a play-test
is long enough that a run with one of them missing is normal, and such a run
looks exactly like a run that found nothing — the session this column came from
was missing `WOW_SYSTEM_TIMING`, so it could say what the UI cost and not what
the frame cost. The script arms the set and prints what it armed.

The test asserts the property the column exists for and not a duration: a
handler called ten times for 50k iterations each outranks one called once for
150k by self time, and the second still has the larger worst call.

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

crates/benilla-app/src/addon_harness/tick_bench_tests.rs

@@ -536,17 +536,29 @@ fn tick_bench() {
             rows.len(),
             total / 1000.0 / per
         );
-        println!("[tick]   self/f(us)  total/f(us)  calls/f  handler");
+        println!("[tick]   self/f(us)  total/f(us)  calls/f   worst(us)  handler");
         for r in rows.iter().take(15) {
             println!(
-                "[tick] {:11.1} {:12.1} {:8.2}  {}:{}",
+                "[tick] {:11.1} {:12.1} {:8.2} {:11.1}  {}:{}",
                 r.self_us / per,
                 r.total_us / per,
                 f64::from(r.calls) / per,
+                r.worst_us,
                 r.frame,
                 r.script
             );
         }
+        // A handler that stalls one frame in five hundred has a mean near zero and never reaches
+        // the table above, so the worst single call is ranked on its own.
+        let mut by_worst: Vec<&benilla_ui::script::HandlerRow> = rows.iter().collect();
+        by_worst.sort_by(|a, b| b.worst_us.total_cmp(&a.worst_us));
+        println!("[tick] {label} worst single call:");
+        for r in by_worst.iter().take(8) {
+            println!(
+                "[tick] {:11.1} us once  (self {:.1} us over {} calls)  {}:{}",
+                r.worst_us, r.self_us, r.calls, r.frame, r.script
+            );
+        }
     }
 
     // ── What one addon bug costs a frame ────────────────────────────────────────────────────

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

@@ -35,12 +35,22 @@ fn env_period() -> Option<f32> {
     })
 }
 
+/// A single call this slow is a dropped frame at any framerate a player plays at, so it is worth
+/// naming on its own even when its mean is nothing.
+const STALL_US: f64 = 2000.0;
+
+/// How many stalling handlers the report names.
+const STALL_ROWS: usize = 8;
+
 /// One `(frame, script)` pair's accumulation over the current window.
 struct Slot {
     script: String,
     calls: u32,
     total_ns: u64,
     self_ns: u64,
+    /// The costliest single call's self time. A handler that stalls a frame once every few
+    /// seconds is invisible in a mean over 500 frames, and a stall is what a player feels.
+    worst_ns: u64,
 }
 
 /// The profiler's state, one per VM, keyed by frame id: names resolve at report time, and a frame
@@ -115,12 +125,14 @@ impl Drop for Fire<'_> {
                 slot.calls += 1;
                 slot.total_ns += total;
                 slot.self_ns += self_ns;
+                slot.worst_ns = slot.worst_ns.max(self_ns);
             }
             None => slots.push(Slot {
                 script: self.script.to_string(),
                 calls: 1,
                 total_ns: total,
                 self_ns,
+                worst_ns: self_ns,
             }),
         }
     }
@@ -137,6 +149,8 @@ pub struct HandlerRow {
     pub self_us: f64,
     /// Microseconds in this handler, including the handlers it fired.
     pub total_us: f64,
+    /// The costliest single call's self time, in microseconds.
+    pub worst_us: f64,
 }
 
 impl UiScript {
@@ -162,33 +176,38 @@ impl UiScript {
     /// This VM's handler costs over the current window as totals, heaviest self time first.
     pub fn handler_profile(&self) -> Vec<HandlerRow> {
         // Snapshot, then release the borrow: labelling reaches into the model and back into Lua.
-        let raw: Vec<(u32, String, u32, u64, u64)> = match self.lua.app_data_ref::<HandlerProf>() {
-            Some(prof) => prof
-                .rows
-                .iter()
-                .flat_map(|(&id, slots)| {
-                    slots.iter().map(move |slot| {
-                        (
-                            id,
-                            slot.script.clone(),
-                            slot.calls,
-                            slot.self_ns,
-                            slot.total_ns,
-                        )
+        let raw: Vec<(u32, String, u32, u64, u64, u64)> =
+            match self.lua.app_data_ref::<HandlerProf>() {
+                Some(prof) => prof
+                    .rows
+                    .iter()
+                    .flat_map(|(&id, slots)| {
+                        slots.iter().map(move |slot| {
+                            (
+                                id,
+                                slot.script.clone(),
+                                slot.calls,
+                                slot.self_ns,
+                                slot.total_ns,
+                                slot.worst_ns,
+                            )
+                        })
                     })
-                })
-                .collect(),
-            None => return Vec::new(),
-        };
+                    .collect(),
+                None => return Vec::new(),
+            };
         let mut rows: Vec<HandlerRow> = raw
             .into_iter()
-            .map(|(id, script, calls, self_ns, total_ns)| HandlerRow {
-                frame: self.handler_label(id, &script),
-                script,
-                calls,
-                self_us: self_ns as f64 / 1000.0,
-                total_us: total_ns as f64 / 1000.0,
-            })
+            .map(
+                |(id, script, calls, self_ns, total_ns, worst_ns)| HandlerRow {
+                    frame: self.handler_label(id, &script),
+                    script,
+                    calls,
+                    self_us: self_ns as f64 / 1000.0,
+                    total_us: total_ns as f64 / 1000.0,
+                    worst_us: worst_ns as f64 / 1000.0,
+                },
+            )
             .collect();
         rows.sort_by(|a, b| {
             b.self_us
@@ -287,13 +306,14 @@ fn print_report(rows: &[HandlerRow], window: f32, frames: u32, nested: u32) {
         total_self / per_frame,
     );
     eprintln!("[ui-handlers] by script: {}", rollup.join("  "));
-    eprintln!("[ui-handlers]   self/f  total/f  calls/f  handler");
+    eprintln!("[ui-handlers]   self/f  total/f  calls/f    worst  handler");
     for row in rows.iter().take(REPORT_ROWS) {
         eprintln!(
-            "[ui-handlers] {:8.1} {:8.1} {:8.2}  {}:{}",
+            "[ui-handlers] {:8.1} {:8.1} {:8.2} {:8.1}  {}:{}",
             row.self_us / per_frame,
             row.total_us / per_frame,
             f64::from(row.calls) / per_frame,
+            row.worst_us,
             row.frame,
             row.script,
         );
@@ -301,10 +321,36 @@ fn print_report(rows: &[HandlerRow], window: f32, frames: u32, nested: u32) {
     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.self_us).sum();
         eprintln!(
-            "[ui-handlers] {:8.1}                    … {rest} more",
+            "[ui-handlers] {:8.1}                             … {rest} more",
             tail / per_frame
         );
     }
+    print_stalls(rows);
+}
+
+/// The handlers whose worst single call cost a frame, which the table above cannot show: it ranks
+/// by the mean, and a handler that stalls once in five hundred frames has a mean near zero. Only
+/// the ones the table left out, so the block says something new or nothing.
+fn print_stalls(rows: &[HandlerRow]) {
+    let mut worst: Vec<&HandlerRow> = rows
+        .iter()
+        .skip(REPORT_ROWS)
+        .filter(|r| r.worst_us >= STALL_US)
+        .collect();
+    if worst.is_empty() {
+        return;
+    }
+    worst.sort_by(|a, b| b.worst_us.total_cmp(&a.worst_us));
+    eprintln!(
+        "[ui-handlers] worst single call, among the {} not listed above:",
+        rows.len() - REPORT_ROWS
+    );
+    for row in worst.iter().take(STALL_ROWS) {
+        eprintln!(
+            "[ui-handlers] {:8.1} us once  (self {:.1} us over {} calls)  {}:{}",
+            row.worst_us, row.self_us, row.calls, row.frame, row.script,
+        );
+    }
 }
 
 /// Install the profiler's `app_data` slot, armed from the environment. Unconditional: mlua refuses

crates/benilla-ui/src/script/tests/handler_prof.rs

@@ -197,3 +197,54 @@ fn disarming_clears_the_window() {
         "and a disarmed VM keeps recording nothing"
     );
 }
+
+/// The column the mean cannot show: a handler that stalls one frame in ten ranks below a steadier
+/// one by self time and still has the larger worst call. The two bodies differ by 3x in work per
+/// the ratio below, which is the margin the ordering rests on — not an absolute duration.
+#[test]
+fn the_worst_call_is_one_calls_cost_and_not_the_mean() {
+    let mut s = armed();
+    s.run(
+        r#"
+        local function burn(n) local x = 0 for i = 1, n do x = x + i end return x end
+        -- 10 calls of 50k: the larger self time, the smaller single call.
+        local steady = CreateFrame("Frame", "Steady")
+        steady:SetScript("OnUpdate", function() burn(50000) end)
+        -- One call of 150k, on the first tick only: the smaller self time, the larger single call.
+        local spiky = CreateFrame("Frame", "Spiky")
+        spiky:SetScript("OnUpdate", function()
+          if not this.done then this.done = true burn(150000) end
+        end)
+        "#,
+    )
+    .unwrap();
+    for _ in 0..10 {
+        s.tick(0.016);
+    }
+    assert!(s.errors().is_empty(), "{:?}", s.errors());
+
+    let rows = s.handler_profile();
+    let steady = row(&rows, "Steady", "OnUpdate").expect("the steady handler");
+    let spiky = row(&rows, "Spiky", "OnUpdate").expect("the spiky handler");
+    assert_eq!((steady.calls, spiky.calls), (10, 10));
+    assert!(
+        steady.self_us > spiky.self_us,
+        "the steady handler costs more over the window, so it ranks first: {rows:#?}"
+    );
+    assert!(
+        spiky.worst_us > steady.worst_us,
+        "and the spiky one's single call is the worse stall, which is the whole point of the \
+         column: {rows:#?}"
+    );
+    assert!(
+        spiky.worst_us <= spiky.self_us,
+        "one call cannot cost more than every call"
+    );
+    let spiky_mean = spiky.self_us / f64::from(spiky.calls);
+    assert!(
+        spiky.worst_us > spiky_mean * 2.0,
+        "nine of its ten calls do nothing, so the mean hides the stall by about tenfold: \
+         worst {:.1} us against a mean of {spiky_mean:.1} us",
+        spiky.worst_us
+    );
+}

measure.sh

@@ -0,0 +1,41 @@
+#!/usr/bin/env bash
+# Launch benilla with the measurement instruments armed, so a play-test answers "where did the
+# frame go?" instead of only "it felt slow".
+#
+#   ./measure.sh             # the standard set: per-system ms, the UI tick split, per handler
+#   ./measure.sh --stalls    # the above plus the per-binding bill, which is noisier and ~2% of a
+#                            # frame; only worth it when a handler's own time is already named
+#
+# Everything ./run.sh does, it does: it builds, it logs to logs/latest.log and logs/errors.log.
+# The instruments print to stderr, which run.sh already captures, so the numbers land in the log
+# beside the errors.
+#
+# Why a script and not a line of environment variables: the set is long, and a run with one of
+# them missing looks exactly like a run that found nothing. This prints what it armed.
+set -euo pipefail
+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 tick, split into its eleven engine phases, with `C_Timer` fires credited to the line that
+# armed them.
+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.
+export WOW_UI_HANDLERS=5
+# The frame's own cost, split main thread against GPU, so a dip says which side it is on.
+export WOW_FLASH_TRACE=1
+export WOW_GPU_MS=1
+
+if [ "${1:-}" = "--stalls" ]; then
+    # Per Lua binding. It wraps the bindings, not the globals — wrapping the globals is what
+    # unloaded a third of the interface once (`setfenv` is level-relative, see
+    # `benilla-ui/src/script/verb_prof.rs`).
+    export WOW_UI_VERBS=5
+    shift
+fi
+
+echo "measure: armed —"
+env | grep -E '^WOW_(SYSTEM_TIMING|UI_TICK|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS)=' | sort | sed 's/^/  /'
+exec "$root/run.sh" "$@"