diff --git a/crates/benilla-app/src/addon_harness/tick_bench_tests.rs b/crates/benilla-app/src/addon_harness/tick_bench_tests.rs index bdf365b2..a95e81e4 100644 --- a/crates/benilla-app/src/addon_harness/tick_bench_tests.rs +++ b/crates/benilla-app/src/addon_harness/tick_bench_tests.rs @@ -773,6 +773,95 @@ fn tick_bench() { // for the whole interface to do it. } + // ── What one quest event costs the interface ──────────────────────────────────────────── + // + // grom's 2026-10-21 session had `[sys-timing]` reporting `ui_quest::feed_quest` at **85.7 ms + // for one run in 76**, fourteen separate times, in bursts of two to six consecutive seconds + // while he turned quests in. Nothing in `feed_quest` is slow: it fires an event, and every + // handler runs synchronously inside the span, so the system holding the stack gets the bill. + // The same window's `[ui-handlers]` named `AceEvent30Frame:OnEvent · calls/f 0.00 · worst + // 72522 us` — a library's shared frame, which is a true row that names no addon and no event. + // + // `WOW_UI_EVENTS` exists for exactly that: the cost of one *fire*, and which frame of the + // fan-out took it. Here it is asked of the real interface, one event at a time from a settled + // start, so each row is that event alone and not a cascade. + { + s.profile_events(true, 0.0); + for _ in 0..30 { + feed_units(&mut s, Company::Grouped); + s.sync_nameplates(GEOMETRY, &plates); + s.tick(1.0 / 60.0); + answer_measures(&mut s); + s.resolve(); + } + let _ = s.take_errors(); + // Every event `ui_quest`, `ui_quest_log` and `ui_quest_share` fire, plus the two the + // reference fires beside them on a turn-in, in the order a turn-in produces them. + for event in [ + "QUEST_DETAIL", + "QUEST_PROGRESS", + "QUEST_COMPLETE", + "QUEST_FINISHED", + "QUEST_ITEM_UPDATE", + "QUEST_LOG_UPDATE", + "QUEST_WATCH_UPDATE", + "UNIT_QUEST_LOG_CHANGED", + "QUEST_TURNED_IN", + "BAG_UPDATE", + "PLAYER_TARGET_CHANGED", + "UNIT_HEALTH", + ] { + // Three fires, because a first fire is not a representative one: an addon's handler + // may be building a table it then keeps, and a cost that never recurs is not what a + // player feels. `us/fire` against `worst` separates the two. + for _ in 0..3 { + s.fire_event(event, Vec::new()); + // Settle: an event's handlers often defer their work to the next `OnUpdate`, and + // that work is the event's whether or not it was charged to the fire. + for _ in 0..3 { + s.tick(1.0 / 60.0); + answer_measures(&mut s); + s.resolve(); + } + } + } + let _ = s.take_errors(); + let rows = s.event_profile(); + println!( + "[events] one fire each, on the settled interface, costliest first ({} rows)", + rows.len() + ); + println!("[events] us/fire worst calls event / worst handler of the worst fire"); + for r in rows.iter().take(12) { + println!( + "[events] {:>8.0} {:>8.0} {:>6} {:<24} {}", + r.self_us / f64::from(r.fires.max(1)), + r.worst_us, + r.calls, + r.event, + r.worst_frame + .as_deref() + .map(|f| format!("{f} ({:.0} us)", r.worst_frame_us)) + .unwrap_or_else(|| "-".into()), + ); + } + s.profile_events(false, 0.0); + // Measured 2026-10-21 on grom's own 92-addon interface, three fires each: + // + // us/fire worst event + // 5068 14759 QUEST_DETAIL <- HCQuest.lua:139 took 14,097 us of ONE fire + // 764 1324 QUEST_LOG_UPDATE + // 662 1564 QUEST_FINISHED + // + // **Read `us/fire` against `worst` before believing either.** QUEST_DETAIL's 14.8 ms is + // one fire of three; the other two cost ~0.1 ms, so it is HCQuest building something once + // and keeping it, not a cost a player pays per quest. With that read correctly, **no quest + // event costs more than ~1.5 ms recurring here** — which means this bench does not + // reproduce the 57-73 ms `feed_quest` spikes of the live session, and says so rather than + // offering a number that looks like an answer. The bench's quest log is empty and pfQuest + // has no real route to recompute; the live `[ui-events]` row is what will attribute it. + } + // ── What one addon bug costs a frame ──────────────────────────────────────────────────── // // mlua's protected call installs a message handler that, for every stack level, searches the diff --git a/crates/benilla-ui/src/script/event.rs b/crates/benilla-ui/src/script/event.rs index 8496f276..75a37a3a 100644 --- a/crates/benilla-ui/src/script/event.rs +++ b/crates/benilla-ui/src/script/event.rs @@ -296,7 +296,22 @@ fn fire( // when the guard drops, unwinds included. let _fire = super::handler_prof::armed().then(|| super::handler_prof::Fire::open(lua, id, script)); - invoke_with_globals(lua, wrapper, &func, event_name, extra) + // `WOW_UI_EVENTS`: the fan-out's own timer cannot see which of its handlers took the time, and + // this is the only place that holds both the event and the frame. Only for a fire that carries + // an event name, so `OnUpdate` keeps its unarmed cost of one atomic load. + if event_name.is_none() || !super::event_prof::armed() { + return invoke_with_globals(lua, wrapper, &func, event_name, extra); + } + let nested_before = super::event_prof::nested_ns(lua); + let started = std::time::Instant::now(); + let out = invoke_with_globals(lua, wrapper, &func, event_name, extra); + // This handler's own time: what it spent, less any event it fired while spending it. Without + // the subtraction every event in a cascade reports the whole cascade and the row that names + // the real cost is the one that looks innocent. + let ns = (started.elapsed().as_nanos() as u64) + .saturating_sub(super::event_prof::nested_ns(lua).wrapping_sub(nested_before)); + super::event_prof::note_handler(lua, id, ns); + out } /// The `argN` global names, spelled out so the common arities allocate nothing. diff --git a/crates/benilla-ui/src/script/event_prof.rs b/crates/benilla-ui/src/script/event_prof.rs new file mode 100644 index 00000000..6b1e8c46 --- /dev/null +++ b/crates/benilla-ui/src/script/event_prof.rs @@ -0,0 +1,360 @@ +//! Per-event cost attribution (`WOW_UI_EVENTS=`): what **one occurrence** of each event +//! costs, summed across every handler it fans out to, plus which frame took the most of it. +//! +//! The gap this fills is a dispatcher. [`super::handler_prof`] keys on `(frame, script)`, which is +//! the right key for an `OnUpdate` and the wrong one for an `OnEvent`, because the addon libraries +//! every interface is built on register **one** frame for **every** event they care about and fan +//! out in Lua. So a 72 ms hitch reads as `AceEvent30Frame:OnEvent · calls/f 0.00 · worst 72522 us` +//! — a true row that names a library's shared frame and no addon, no event and no cause. In grom's +//! 2026-10-21 session that one row was the largest identifiable cost in the game, eleven times. +//! +//! An event's cost is not a frame's cost and not a handler's cost: it is what the engine pays for +//! deciding to tell the interface something, which is the thing engine code chooses and can stop +//! choosing. `[sys-timing]` can see that total — `ui_quest::feed_quest` read 85.7 ms, one run in +//! 76 — but only as the system that happened to be holding the stack, since every handler runs +//! synchronously inside whichever system fired. This report is that number broken out by event. +//! +//! Two timers per handler fire while armed, and a relaxed atomic load per fire while not. + +use std::collections::HashMap; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::time::Instant; + +use mlua::Lua; + +use super::UiScript; + +/// How many events the periodic report prints before rolling the rest into a `… N more` line. +const REPORT_ROWS: usize = 14; + +/// A single fan-out this slow is a dropped frame at any framerate a player plays at. +const STALL_US: f64 = 2000.0; + +/// Whether any VM in the process profiles events: process-wide, so the per-fire check needs no +/// `app_data` lookup. +static ARMED: AtomicBool = AtomicBool::new(false); + +#[inline] +pub(super) fn armed() -> bool { + ARMED.load(Ordering::Relaxed) +} + +/// The report period from `WOW_UI_EVENTS=`, read once; unparseable or non-positive is off. +fn env_period() -> Option { + static PERIOD: std::sync::OnceLock> = std::sync::OnceLock::new(); + *PERIOD.get_or_init(|| { + std::env::var("WOW_UI_EVENTS") + .ok() + .and_then(|v| v.parse::().ok()) + .filter(|secs| *secs > 0.0) + }) +} + +/// One event name's accumulation over the current window. +#[derive(Default, Clone)] +struct Slot { + /// Occurrences of the event, not handler calls: one `fire_event` is one fire however many + /// frames listen. + fires: u32, + /// Handler calls those fires made, so a cost can be read against a fan-out width. + calls: u32, + /// Every handler of every fire, with the cost of events those handlers fired in turn taken + /// out — so a cascade's total is not charged to every event in it. Work a handler provokes + /// that is *not* another event (a layout resolve, an `OnShow` it triggered) stays here, where + /// it belongs: the event is why it happened. + self_ns: u64, + /// The same including events its handlers fired in turn. + total_ns: u64, + /// The costliest single fan-out, and the frame that took the most of *that* fan-out. The mean + /// is not what a player feels and the fan-out's widest handler is where to look first. + worst_ns: u64, + worst_frame: Option, + worst_frame_ns: u64, +} + +/// The profiler's state, one per VM, keyed by event name. +#[derive(Default)] +pub(crate) struct EventProf { + /// Whether this VM records; [`armed`] is the process-wide gate. + on: bool, + /// Seconds between reports; `0.0` records and never prints. + period: f32, + /// Wall seconds and frames since the last report, the divisor of every printed rate. + window: f32, + frames: u32, + /// Nanos already charged to nested fires, one entry per open fan-out. + stack: Vec, + /// Every nested fan-out's cost since this VM started, monotonic. [`note_handler`]'s caller + /// reads it either side of a handler to subtract the events that handler fired, which is the + /// only way to tell "this handler is slow" from "this handler fired a slow event". + nested_ns: u64, + /// The open fan-out's running handler tally: `(calls, self ns, worst frame, worst frame ns)`. + open: Vec<(u32, u64, Option, u64)>, + rows: HashMap, +} + +/// An open fan-out, closed by its `Drop`, so the nesting stack stays balanced through an unwind. +pub(super) struct Dispatch<'a> { + lua: &'a Lua, + event: &'a str, + /// `None` while this VM is not recording, which makes the guard a no-op. + started: Option, +} + +impl<'a> Dispatch<'a> { + /// Open a fan-out of `event`. Cheap and inert unless this VM is recording. + pub(super) fn open(lua: &'a Lua, event: &'a str) -> Dispatch<'a> { + let started = match lua.app_data_mut::() { + Some(mut prof) if prof.on => { + prof.stack.push(0); + prof.open.push((0, 0, None, 0)); + Some(Instant::now()) + } + _ => None, + }; + Dispatch { + lua, + event, + started, + } + } +} + +impl Drop for Dispatch<'_> { + fn drop(&mut self) { + let Some(started) = self.started else { + return; + }; + let total = started.elapsed().as_nanos() as u64; + let Some(mut prof) = self.lua.app_data_mut::() else { + return; + }; + let children = prof.stack.pop().unwrap_or(0); + if let Some(parent) = prof.stack.last_mut() { + *parent += total; + } + // Unconditional: a top-level fan-out cannot be inside a handler, since a handler only runs + // inside a fan-out, so nothing reads this across one. + prof.nested_ns = prof.nested_ns.wrapping_add(total); + let (calls, self_ns, worst_frame, worst_frame_ns) = prof.open.pop().unwrap_or_default(); + let slot = prof.rows.entry(self.event.to_string()).or_default(); + slot.fires += 1; + slot.calls += calls; + slot.self_ns += self_ns; + slot.total_ns += total; + // The fan-out's own handlers, not the nested events they triggered: a hitch is charged to + // the event whose handlers ran, and a nested event gets its own row for its own. + let fanout = total.saturating_sub(children); + if fanout > slot.worst_ns { + slot.worst_ns = fanout; + slot.worst_frame = worst_frame; + slot.worst_frame_ns = worst_frame_ns; + } + } +} + +/// Nanos spent in nested fan-outs so far, for [`note_handler`]'s caller to difference across a +/// handler. Zero when this VM is not recording. +pub(super) fn nested_ns(lua: &Lua) -> u64 { + lua.app_data_ref::() + .filter(|prof| prof.on) + .map_or(0, |prof| prof.nested_ns) +} + +/// Charge one handler call of the open fan-out, `ns` being its own time with any event it fired +/// taken out. Called from [`super::event::fire`], which is the only place that knows both the +/// event name and the frame. +pub(super) fn note_handler(lua: &Lua, id: u32, ns: u64) { + let Some(mut prof) = lua.app_data_mut::() else { + return; + }; + if !prof.on { + return; + } + let Some(open) = prof.open.last_mut() else { + return; + }; + open.0 += 1; + open.1 += ns; + if ns > open.3 { + open.2 = Some(id); + open.3 = ns; + } +} + +/// One event's cost over the profiler's current window. +#[derive(Clone, Debug, PartialEq)] +pub struct EventRow { + pub event: String, + /// Occurrences, not handler calls. + pub fires: u32, + pub calls: u32, + pub self_us: f64, + pub total_us: f64, + /// The costliest single fan-out. + pub worst_us: f64, + /// The frame that took the most of that fan-out, already labelled. + pub worst_frame: Option, + pub worst_frame_us: f64, +} + +impl UiScript { + /// Arm or disarm event profiling for this VM, as [`UiScript::profile_handlers`] does for + /// handlers. `period_secs` of `0.0` records without printing, for a test or a bench. + pub fn profile_events(&self, on: bool, period_secs: f32) { + if let Some(mut prof) = self.lua.app_data_mut::() { + prof.on = on; + prof.period = period_secs; + } + if on { + ARMED.store(true, Ordering::Relaxed); + } + } + + /// Every event's cost this window, costliest first by the self time of its handlers. + pub fn event_profile(&self) -> Vec { + // Snapshot first and label after: `handler_label` borrows the model, and the profiler's + // own borrow must be released before it does. + let raw: Vec<(String, Slot)> = { + let Some(prof) = self.lua.app_data_ref::() else { + return Vec::new(); + }; + prof.rows + .iter() + .map(|(event, slot)| (event.clone(), slot.clone())) + .collect() + }; + let mut rows: Vec = raw + .into_iter() + .map(|(event, s)| EventRow { + event, + fires: s.fires, + calls: s.calls, + self_us: ns_to_us(s.self_ns), + total_us: ns_to_us(s.total_ns), + worst_us: ns_to_us(s.worst_ns), + worst_frame: s.worst_frame.map(|id| self.handler_label(id, "OnEvent")), + worst_frame_us: ns_to_us(s.worst_frame_ns), + }) + .collect(); + rows.sort_by(|a, b| { + b.self_us + .total_cmp(&a.self_us) + .then_with(|| a.event.cmp(&b.event)) + }); + rows + } + + pub(super) fn report_event_profile(&mut self, elapsed: f32) { + if !armed() { + return; + } + let due = match self.lua.app_data_mut::() { + Some(mut prof) if prof.on => { + prof.frames += 1; + prof.window += elapsed; + prof.period > 0.0 && prof.window >= prof.period + } + _ => false, + }; + if !due { + return; + } + // The rows first: the label walk's model borrow must end before the profiler's mutable one. + let rows = self.event_profile(); + let mut prof = self + .lua + .app_data_mut::() + .expect("profiler app_data — checked above"); + print_report(&rows, prof.window, prof.frames); + prof.window = 0.0; + prof.frames = 0; + prof.rows.clear(); + } +} + +#[allow(clippy::cast_precision_loss)] +fn ns_to_us(ns: u64) -> f64 { + ns as f64 / 1000.0 +} + +/// The `[ui-events]` block: the window, then the costliest [`REPORT_ROWS`] events by the self time +/// of their handlers, then the stalling ones the table left out. +fn print_report(rows: &[EventRow], window: f32, frames: u32) { + let per_frame = f64::from(frames.max(1)); + let fires: u32 = rows.iter().map(|r| r.fires).sum(); + let total: f64 = rows.iter().map(|r| r.self_us).sum(); + eprintln!( + "[ui-events] {window:.2}s · {frames} frames · {} event(s) · {fires} fire(s) · \ + {:.1} us/f in handlers", + rows.len(), + total / per_frame, + ); + eprintln!("[ui-events] us/f fires/f us/fire worst worst handler / event"); + for row in rows.iter().take(REPORT_ROWS) { + let per_fire = row.self_us / f64::from(row.fires.max(1)); + eprintln!( + "[ui-events] {:>6.1} {:>8.2} {:>8.1} {:>8.1} {} · {}", + row.self_us / per_frame, + f64::from(row.fires) / per_frame, + per_fire, + row.worst_us, + row.event, + describe_worst(row), + ); + } + if rows.len() > REPORT_ROWS { + let rest: f64 = rows.iter().skip(REPORT_ROWS).map(|r| r.self_us).sum(); + eprintln!( + "[ui-events] {:>6.1} … {} more", + rest / per_frame, + rows.len() - REPORT_ROWS + ); + } + // The events the table's own ranking hides: one that fires once a minute and costs 70 ms when + // it does has no mean worth printing and is the only thing the player noticed. + let mut stalls: Vec<&EventRow> = rows + .iter() + .skip(REPORT_ROWS) + .filter(|r| r.worst_us >= STALL_US) + .collect(); + stalls.sort_by(|a, b| b.worst_us.total_cmp(&a.worst_us)); + if !stalls.is_empty() { + eprintln!("[ui-events] worst single fan-out, among the events not listed above:"); + for row in stalls.iter().take(REPORT_ROWS) { + eprintln!( + "[ui-events] {:>8.1} us over {} fire(s) {} · {}", + row.worst_us, + row.fires, + row.event, + describe_worst(row), + ); + } + } +} + +/// `most of it in ()`, or a note that no handler was timed — an event with listeners +/// that all unregistered mid-walk, or one fired with nothing registered at all. +fn describe_worst(row: &EventRow) -> String { + match &row.worst_frame { + Some(frame) => format!( + "{} call(s), worst in {frame} ({:.1} us)", + row.calls, row.worst_frame_us + ), + None => format!("{} call(s), no handler timed", row.calls), + } +} + +/// Install the profiler's `app_data` slot, armed from the environment. Unconditional: mlua refuses +/// to insert app data while any is borrowed, so the slot must exist before the VM runs. +pub(super) fn install(lua: &Lua) { + let period = env_period(); + lua.set_app_data(EventProf { + on: period.is_some(), + period: period.unwrap_or_default(), + ..EventProf::default() + }); + if period.is_some() { + ARMED.store(true, Ordering::Relaxed); + } +} diff --git a/crates/benilla-ui/src/script/handler_prof.rs b/crates/benilla-ui/src/script/handler_prof.rs index 1b10c131..e71e4947 100644 --- a/crates/benilla-ui/src/script/handler_prof.rs +++ b/crates/benilla-ui/src/script/handler_prof.rs @@ -258,7 +258,7 @@ impl UiScript { impl UiScript { /// A row's label: the frame's name, else the handler's `:` (an unnamed frame is the /// common addon timer), else `#`. - fn handler_label(&self, id: u32, script: &str) -> String { + pub(super) fn handler_label(&self, id: u32, script: &str) -> String { let named = { let model = self.model_ref(); model diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index 4e450b84..96113290 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -57,6 +57,7 @@ mod cvars; mod dressup; mod duel; pub(crate) mod event; +mod event_prof; mod extract; mod follow; pub(crate) mod font; @@ -69,6 +70,7 @@ mod raise_prof; mod screenshot; mod tabard; mod tick_prof; +pub use event_prof::EventRow; pub use handler_prof::HandlerRow; pub use raise_prof::RaiseRow; pub use tick_prof::{Phase as TickPhase, TickPhaseRow, TimerSiteRow}; @@ -535,6 +537,7 @@ impl UiScript { // Before anything can fire a handler and while no app-data borrow is held, as the // profiler's slot requires. handler_prof::install(&lua); + event_prof::install(&lua); // Beside it, and for the same reason: the slot must exist before anything can tick. tick_prof::install(&lua); diff --git a/crates/benilla-ui/src/script/tests/event_prof.rs b/crates/benilla-ui/src/script/tests/event_prof.rs new file mode 100644 index 00000000..c204f20f --- /dev/null +++ b/crates/benilla-ui/src/script/tests/event_prof.rs @@ -0,0 +1,182 @@ +//! Per-event cost attribution. The tests assert names, fan-out widths and which frame a fan-out's +//! time was charged to, never a duration — except where one handler is made deliberately slower +//! than another and only their *order* is asserted. + +use super::common::script; +use crate::script::{EventRow, ScriptValue, UiScript}; + +fn row(rows: &[EventRow], event: &str) -> Option { + rows.iter().find(|r| r.event == event).cloned() +} + +/// Recording, with no periodic report: the tests read the window directly. +fn armed() -> UiScript { + let s = script(); + s.profile_events(true, 0.0); + s +} + +/// Enough Lua to be reliably slower than an empty handler, without a clock read: `GetTime()` only +/// advances once a tick, so a handler cannot wait, it can only work. +const BUSY: &str = "local t = {} for i = 1, 40000 do t[i] = i * 2 end"; + +#[test] +fn an_events_cost_is_charged_to_the_event_and_not_to_the_library_frame() { + let mut s = armed(); + // The shape that made this profiler necessary: *one* frame registered for several events, as + // every addon library does, so `(frame, script)` cannot tell the events apart. + s.run(&format!( + r#" + local lib = CreateFrame("Frame", "LibraryFrame") + lib:RegisterEvent("QUEST_LOG_UPDATE") + lib:RegisterEvent("BAG_UPDATE") + lib:SetScript("OnEvent", function() + if event == "QUEST_LOG_UPDATE" then {BUSY} end + end) + "# + )) + .unwrap(); + + s.fire_event("BAG_UPDATE", vec![]); + s.fire_event("QUEST_LOG_UPDATE", vec![]); + assert!(s.errors().is_empty(), "{:?}", s.errors()); + + let rows = s.event_profile(); + let heavy = row(&rows, "QUEST_LOG_UPDATE").expect("the busy event has a row"); + let light = row(&rows, "BAG_UPDATE").expect("the quiet event has a row"); + assert_eq!((heavy.fires, heavy.calls), (1, 1)); + assert_eq!((light.fires, light.calls), (1, 1)); + assert!( + heavy.self_us > light.self_us, + "the cost must follow the event, not the frame both share — the whole point of the \ + instrument: {rows:#?}" + ); + assert_eq!( + heavy.worst_frame.as_deref(), + Some("LibraryFrame"), + "and the fan-out's costliest handler is named: {rows:#?}" + ); + // Costliest first, so the report's top row is the one to read. + assert_eq!( + rows.first().map(|r| r.event.as_str()), + Some("QUEST_LOG_UPDATE") + ); +} + +#[test] +fn one_fire_is_one_fire_however_wide_it_fans_out() { + let mut s = armed(); + s.run(&format!( + r#" + for i = 1, 4 do + local f = CreateFrame("Frame", "Listener"..i) + f:RegisterEvent("UNIT_HEALTH") + f:SetScript("OnEvent", function() if i == 3 then {BUSY} end end) + end + "# + )) + .unwrap(); + + for _ in 0..3 { + s.fire_event("UNIT_HEALTH", vec![ScriptValue::Str("player".into())]); + } + assert!(s.errors().is_empty(), "{:?}", s.errors()); + + let r = row(&s.event_profile(), "UNIT_HEALTH").expect("row"); + assert_eq!(r.fires, 3, "three dispatches are three fires"); + assert_eq!(r.calls, 12, "each one called all four listeners"); + assert_eq!( + r.worst_frame.as_deref(), + Some("Listener3"), + "the slow listener is named, not the first or the last" + ); + assert!( + r.worst_us >= r.worst_frame_us, + "a fan-out cannot cost less than the handler inside it" + ); + assert!( + r.self_us >= r.worst_us, + "three fires cannot total less than the worst one" + ); +} + +#[test] +fn a_nested_event_is_charged_to_itself_and_not_twice() { + let mut s = armed(); + // An outer handler that fires another event: the pattern behind the `feed_quest` reading, + // where one engine event provokes a cascade and `[sys-timing]` can only see the total. + s.run(&format!( + r#" + local outer = CreateFrame("Frame", "Outer") + outer:RegisterEvent("OUTER_EVENT") + outer:SetScript("OnEvent", function() + BenillaFireInner() + end) + local inner = CreateFrame("Frame", "Inner") + inner:RegisterEvent("INNER_EVENT") + inner:SetScript("OnEvent", function() {BUSY} end) + "# + )) + .unwrap(); + // The nested fire has to come from the engine's own path, which is what a Lua binding firing an + // event does; `fire_event` from Rust is not reentrant into a running handler. + let lua = s.lua(); + let f = lua + .create_function(|lua, ()| { + crate::script::tick::fire_event_into(lua, "INNER_EVENT", Vec::new()); + Ok(()) + }) + .unwrap(); + lua.globals().set("BenillaFireInner", f).unwrap(); + + s.fire_event("OUTER_EVENT", vec![]); + assert!(s.errors().is_empty(), "{:?}", s.errors()); + + let rows = s.event_profile(); + let outer = row(&rows, "OUTER_EVENT").expect("outer row"); + let inner = row(&rows, "INNER_EVENT").expect("inner row"); + assert_eq!((outer.fires, inner.fires), (1, 1)); + assert!( + inner.self_us > outer.self_us, + "the work was the inner event's, so the inner row owns it: {rows:#?}" + ); + assert!( + outer.total_us >= inner.total_us, + "the outer event's total includes what it provoked, which is how a cascade reads" + ); + assert!( + outer.worst_us < outer.total_us, + "but its worst fan-out excludes it, or every event in a cascade reports the cascade" + ); +} + +#[test] +fn an_event_nobody_listens_to_still_reports_that_it_fired() { + let mut s = armed(); + s.fire_event("NOBODY_HOME", vec![]); + let r = + row(&s.event_profile(), "NOBODY_HOME").expect("a fire with no listener is still a fire"); + assert_eq!((r.fires, r.calls), (1, 0)); + assert_eq!( + r.worst_frame, None, + "and names no frame rather than inventing one" + ); +} + +#[test] +fn unarmed_the_profiler_records_nothing() { + let mut s = script(); + s.run( + r#" + local f = CreateFrame("Frame", "Listener") + f:RegisterEvent("UNIT_HEALTH") + f:SetScript("OnEvent", function() end) + "#, + ) + .unwrap(); + s.fire_event("UNIT_HEALTH", vec![]); + assert!( + s.event_profile().is_empty(), + "an unarmed VM must not pay for a window it will never print" + ); +} diff --git a/crates/benilla-ui/src/script/tests/mod.rs b/crates/benilla-ui/src/script/tests/mod.rs index 9203e7a4..28d191ea 100644 --- a/crates/benilla-ui/src/script/tests/mod.rs +++ b/crates/benilla-ui/src/script/tests/mod.rs @@ -15,6 +15,7 @@ mod cooldown; mod create_frame_template; mod dispatch_bench; mod end_to_end; +mod event_prof; mod events; mod font_object; mod frame_api; diff --git a/crates/benilla-ui/src/script/tick.rs b/crates/benilla-ui/src/script/tick.rs index 87a37d1d..c8017407 100644 --- a/crates/benilla-ui/src/script/tick.rs +++ b/crates/benilla-ui/src/script/tick.rs @@ -43,6 +43,10 @@ impl UiScript { /// [`UiScript::fire_event`] for a caller holding `&Lua`, such as a Lua binding. pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) { let model_mut = || lua.app_data_mut::().expect("model app_data set"); + // `WOW_UI_EVENTS=`: this whole fan-out is one fire of `event`, which is the unit a + // dropped frame is measured in. Inert and one atomic load unarmed. + let _dispatch = + super::event_prof::armed().then(|| super::event_prof::Dispatch::open(lua, event)); { let mut at = { let model = model_mut(); @@ -266,6 +270,9 @@ impl super::UiScript { // `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_EVENTS=`: the same window one level *up* — which event the `OnEvent` rows + // above were answering, since the libraries fan out from one frame. + self.report_event_profile(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/measure.sh b/measure.sh index 0cf47334..3883ad5a 100755 --- a/measure.sh +++ b/measure.sh @@ -5,6 +5,9 @@ # ./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 +# ./measure.sh --frames # the above plus the per-frame phase split and the render thread's +# # own stages, for a spike no per-system number accounts for; both +# # perturb what they measure, so this is not the baseline set # # 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 @@ -27,6 +30,12 @@ export WOW_UI_PHASES=5 # The UI tick, split into its eleven engine phases, with `C_Timer` fires credited to the line that # armed them. Inside WOW_UI_PHASES' `tick` row. export WOW_UI_TICK=5 +# Per event: what one fire of each event costs across every handler it reaches, and which frame +# took the most of the worst one. The handler report below keys on (frame, script), which is the +# wrong key for an OnEvent, because every addon library registers one frame for every event it +# wants and fans out in Lua — so a 72 ms hitch reads as `AceEvent30Frame:OnEvent`, naming a +# library's shared frame and no addon, no event and no cause. +export WOW_UI_EVENTS=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 @@ -34,6 +43,25 @@ export WOW_UI_HANDLERS=5 export WOW_FLASH_TRACE=1 export WOW_GPU_MS=1 +if [ "${1:-}" = "--frames" ]; then + # For a spike that `[sys-timing]` cannot see. A frame's wall time is `max(main app, render + # app)` because bevy pipelines the render app onto its own thread, so when the render app is + # the longer of the two, `wall` climbs while `cpu`, `main`, `gpu` and every per-system `worst` + # all read healthy. grom's 2026-10-21 session had exactly that: a 161 ms frame in a second + # whose costliest system worst was 2.9 ms over 105 runs. + # + # `WOW_FRAME_PHASES` prints one line per frame over the threshold, with everything outside + # `Main` as its `render+present` remainder — that is the fork: Main or not. `WOW_RENDER_MS` + # then says which render stage, if it is not. + # + # Its own mode because both perturb what they measure: the phase stamps are exclusive systems + # between `Update`'s four `WorldStage` sets, and the render stamps add nine sync points to the + # render thread. Use it to answer a spike question, not to measure a baseline. + export WOW_FRAME_PHASES=50 + export WOW_RENDER_MS=1 + shift +fi + 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 @@ -43,5 +71,5 @@ if [ "${1:-}" = "--stalls" ]; then fi echo "measure: armed —" -env | grep -E '^WOW_(SYSTEM_TIMING|UI_PHASES|UI_TICK|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS)=' | sort | sed 's/^/ /' +env | grep -E '^WOW_(SYSTEM_TIMING|UI_PHASES|UI_TICK|UI_EVENTS|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS|FRAME_PHASES|RENDER_MS)=' | sort | sed 's/^/ /' exec "$root/run.sh" "$@"