verbs: an instrument that charges a load's time to the binding it went into

`WOW_UI_HANDLERS` names the handler and `WOW_UI_TICK` names the tick phase, and between them they left the question this answers. A reload of the player's interface spends **4.47 s inside handler bodies**, and single calls in there cost hundreds of milliseconds — `pfBag:OnHide` 394 ms in ONE call — which is not Lua arithmetic. A handler's self time includes the engine work it provokes, so that time is ours: it is inside the verbs the handler called, and nothing charged it to them. `WOW_UI_VERBS=1` wraps every global and every widget method at the end of `UiScript::new` — before FrameXML or any addon runs, so everything it finds is ours — and times each call. Off, nothing is wrapped and nothing is paid. It works offline, which matters more than the live case: the addon harness's `--together` mode loads the player's whole folder into one VM in load order, which is the closest thing to a login burst that needs no server. The first run over his 91 addons, three passes: ``` [ui-verbs] 519 verbs, 17,966,414 calls, 9,148 ms in all 4384 6393 685.8 us pcall (addon code, nested) 1498 16071556 0.1 us type (5.4M calls a load, Ace's) 1241 1950 636.2 us frame:GetWidth ← 650 calls a load at 0.6 ms each 548 33093 16.6 us CreateFrame 219 37524 5.8 us fontstring:SetPoint 95 99 960.3 us frame:GetHeight 67 123 545.9 us frame:GetLeft 17 3 5628.6 us frame:GetCenter ``` A geometry read costing 636 µs is the whole finding, and the fix is the next commit. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn
2026-10-18 18:51:45 -06:00
parent 3369d525cb
commit c5911ccd6f
4 changed files with 170 additions and 1 deletions
@@ -241,6 +241,9 @@ fn main() {
    // bound; `--diff <a survey roster>` names the rows the bound costs.
    if rest.iter().any(|a| a == "--together") {
        let rows = addon_harness::together::survey_together(&root);
+        // `WOW_UI_VERBS=1` turns this run into the load's per-verb bill: the whole folder in one
+        // VM is the closest thing to a login burst that needs no server.
+        benilla_ui::script::verb_prof::log_report("the whole folder in one VM", 24);
        if rows.is_empty() {
            eprintln!(
                "no addons under {} — is that an AddOns folder?",
@@ -74,6 +74,7 @@ pub use raise_prof::RaiseRow;
 pub use tick_prof::{Phase as TickPhase, TickPhaseRow, TimerSiteRow};

 mod surface;
+pub mod verb_prof;
 pub use surface::widget_method_census;
 mod inspect;
 mod item_stats;
@@ -627,6 +628,10 @@ impl UiScript {
        // most of all — so `WOW_UI_RAISES`' wrappers are seen only by the addon code that loads
        // next, and the dispatch paths the host already logs stay on the stock pair.
        raise_prof::install(&lua)?;
+        // Last of all, and only when armed: it wraps every binding installed above, so anything
+        // installed after it would go unmeasured, and anything loaded after it (FrameXML, addons)
+        // is not ours to call a verb.
+        verb_prof::install(&lua)?;

        let s = UiScript {
            lua,
@@ -11,7 +11,7 @@ use super::UiScript;

 /// The VM's named-registry method tables: every widget method benilla registers is a key in one,
 /// and the per-instance probe decides which a class answers.
-const METHOD_TABLES: &[&str] = &[
+pub(super) const METHOD_TABLES: &[&str] = &[
    "__benilla_frame_methods",
    "__benilla_region_methods",
    "__benilla_texture_methods",
@@ -0,0 +1,161 @@
+//! Per-verb attribution (`WOW_UI_VERBS=1`): which **binding** an addon's time goes into.
+//!
+//! [`super::handler_prof`] names the handler and [`super::tick_prof`] names the tick phase, and
+//! between them they leave the question this answers. A reload of the player's interface spends
+//! 4.47 s inside handler bodies, and single calls there cost hundreds of milliseconds —
+//! `pfBag:OnHide` 394 ms in ONE call — which is not Lua arithmetic. A handler's self time includes
+//! the engine work it provokes, so that time is ours: it is inside the verbs the handler called
+//! (`CreateFrame`, `SetPoint`, `SetTexture`, `Show`), and nothing charged it to them.
+//!
+//! **How it attaches.** Armed, [`install`] walks `_G` and every widget method table at the end of
+//! [`UiScript::new`](super::UiScript::new) — before any FrameXML or addon runs, so everything it
+//! finds is ours — and replaces each function with a closure that times the call. A verb that
+//! 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.
+//!
+//! 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.
+
+use std::collections::HashMap;
+use std::sync::atomic::{AtomicBool, Ordering};
+use std::sync::Mutex;
+use std::time::Instant;
+
+use mlua::{Lua, MultiValue, Table, Value};
+
+/// `(calls, nanos)` per verb name, process-wide: the VM is single-threaded, so this lock is
+/// uncontended, and a process-wide table lets a harness that builds several VMs read one total.
+static ROWS: Mutex<Option<HashMap<String, (u64, u128)>>> = Mutex::new(None);
+static ARMED: AtomicBool = AtomicBool::new(false);
+
+/// Whether `WOW_UI_VERBS` armed the profiler, read once.
+pub fn armed() -> bool {
+    static ON: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
+    *ON.get_or_init(|| {
+        let on = std::env::var_os("WOW_UI_VERBS").is_some_and(|v| !v.is_empty() && v != "0");
+        ARMED.store(on, Ordering::Relaxed);
+        on
+    })
+}
+
+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);
+    let slot = rows.entry(name.to_string()).or_insert((0, 0));
+    slot.0 += 1;
+    slot.1 += nanos;
+}
+
+/// One verb's cost over the process's life.
+pub struct VerbRow {
+    pub name: String,
+    pub calls: u64,
+    pub micros: f64,
+}
+
+/// Every verb called so far, costliest first.
+pub fn report() -> Vec<VerbRow> {
+    let rows = ROWS.lock().unwrap_or_else(|p| p.into_inner());
+    let mut out: Vec<VerbRow> = rows
+        .as_ref()
+        .map(|m| {
+            m.iter()
+                .map(|(name, (calls, nanos))| VerbRow {
+                    name: name.clone(),
+                    calls: *calls,
+                    micros: *nanos as f64 / 1000.0,
+                })
+                .collect()
+        })
+        .unwrap_or_default();
+    out.sort_by(|a, b| b.micros.total_cmp(&a.micros).then(a.name.cmp(&b.name)));
+    out
+}
+
+/// Print the table, as the other profilers print theirs: the header, then `rows` lines.
+pub fn log_report(label: &str, rows: usize) {
+    if !armed() {
+        return;
+    }
+    let all = report();
+    let total: f64 = all.iter().map(|r| r.micros).sum();
+    let calls: u64 = all.iter().map(|r| r.calls).sum();
+    eprintln!(
+        "[ui-verbs] {label}: {} verbs, {calls} calls, {:.0} ms in all",
+        all.len(),
+        total / 1000.0
+    );
+    eprintln!("[ui-verbs]     ms    calls    us/call  verb");
+    for r in all.iter().take(rows) {
+        eprintln!(
+            "[ui-verbs] {:6.0} {:8} {:10.1}  {}",
+            r.micros / 1000.0,
+            r.calls,
+            r.micros / r.calls.max(1) as f64,
+            r.name
+        );
+    }
+    if let Some(rest) = all.len().checked_sub(rows).filter(|n| *n > 0) {
+        let tail: f64 = all.iter().skip(rows).map(|r| r.micros).sum();
+        eprintln!(
+            "[ui-verbs] {:6.0}                     … {rest} more",
+            tail / 1000.0
+        );
+    }
+}
+
+/// Forget everything measured, so a harness can bound a phase.
+pub fn reset() {
+    *ROWS.lock().unwrap_or_else(|p| p.into_inner()) = None;
+}
+
+/// Wrap one table's function values in place, naming each `<prefix><key>`.
+fn wrap_table(lua: &Lua, table: &Table, prefix: &str) -> mlua::Result<usize> {
+    let mut wrapped = 0;
+    let keys: Vec<String> = table
+        .clone()
+        .pairs::<Value, Value>()
+        .filter_map(|p| p.ok())
+        .filter_map(|(k, v)| match (k, v) {
+            (Value::String(k), Value::Function(_)) => k.to_str().ok().map(|s| s.to_string()),
+            _ => None,
+        })
+        .collect();
+    for key in keys {
+        let Ok(Value::Function(orig)) = table.raw_get::<Value>(key.as_str()) else {
+            continue;
+        };
+        let name = format!("{prefix}{key}");
+        let timed = lua.create_function(move |_, args: MultiValue| {
+            let started = Instant::now();
+            let out = orig.call::<MultiValue>(args);
+            record(&name, started.elapsed().as_nanos());
+            out
+        })?;
+        table.raw_set(key, timed)?;
+        wrapped += 1;
+    }
+    Ok(wrapped)
+}
+
+/// Arm the profiler on a freshly built VM: every global and every widget method, timed. Called at
+/// the end of [`UiScript::new`](super::UiScript::new), where `_G` holds our bindings and nothing
+/// else — a later call would wrap FrameXML's own functions too and call them verbs.
+pub(super) fn install(lua: &Lua) -> mlua::Result<()> {
+    if !armed() {
+        return Ok(());
+    }
+    let mut n = wrap_table(lua, &lua.globals(), "")?;
+    for reg in super::surface::METHOD_TABLES {
+        if let Ok(table) = lua.named_registry_value::<Table>(reg) {
+            // `__benilla_frame_methods` → `frame:`, so a row reads as the addon wrote the call.
+            let short = reg
+                .strip_prefix("__benilla_")
+                .and_then(|r| r.strip_suffix("_methods"))
+                .unwrap_or(reg);
+            n += wrap_table(lua, &table, &format!("{short}:"))?;
+        }
+    }
+    eprintln!("[ui-verbs] armed — {n} verbs timed (WOW_UI_VERBS)");
+    Ok(())
+}