From c5911ccd6f788e2992f520ae5033e3d237a49392 Mon Sep 17 00:00:00 2001 From: grom Date: Sun, 18 Oct 2026 18:51:45 -0600 Subject: [PATCH] verbs: an instrument that charges a load's time to the binding it went into MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/examples/addon_harness.rs | 3 + crates/benilla-ui/src/script/mod.rs | 5 + crates/benilla-ui/src/script/surface.rs | 2 +- crates/benilla-ui/src/script/verb_prof.rs | 161 +++++++++++++++++++ 4 files changed, 170 insertions(+), 1 deletion(-) create mode 100644 crates/benilla-ui/src/script/verb_prof.rs diff --git a/crates/benilla-app/examples/addon_harness.rs b/crates/benilla-app/examples/addon_harness.rs index 7047407d..6d8820de 100644 --- a/crates/benilla-app/examples/addon_harness.rs +++ b/crates/benilla-app/examples/addon_harness.rs @@ -241,6 +241,9 @@ fn main() { // bound; `--diff ` 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?", diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index 00b4daa4..9b70bb81 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -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, diff --git a/crates/benilla-ui/src/script/surface.rs b/crates/benilla-ui/src/script/surface.rs index a6e4ae9f..db683733 100644 --- a/crates/benilla-ui/src/script/surface.rs +++ b/crates/benilla-ui/src/script/surface.rs @@ -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", diff --git a/crates/benilla-ui/src/script/verb_prof.rs b/crates/benilla-ui/src/script/verb_prof.rs new file mode 100644 index 00000000..c048570c --- /dev/null +++ b/crates/benilla-ui/src/script/verb_prof.rs @@ -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>> = 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 = 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 { + let rows = ROWS.lock().unwrap_or_else(|p| p.into_inner()); + let mut out: Vec = 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 ``. +fn wrap_table(lua: &Lua, table: &Table, prefix: &str) -> mlua::Result { + let mut wrapped = 0; + let keys: Vec = table + .clone() + .pairs::() + .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::(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::(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::(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(()) +}