ui: name the event, not the library frame that dispatched it
`WOW_UI_EVENTS=<secs>` (`script/event_prof.rs`): per event, what one fire
costs across every handler it reaches, and which frame took the most of the
worst fire.
The gap it fills is a dispatcher. `WOW_UI_HANDLERS` keys on `(frame, script)`,
which is the right key for an `OnUpdate` and the wrong one for an `OnEvent`,
because every addon library registers *one* frame for *every* event it wants and
fans out in Lua. So the largest identifiable cost in grom's 2026-10-21 session,
eleven separate times, read as
[ui-handlers] 312.5 312.5 0.00 72522.3 AceEvent30Frame:OnEvent
— a true row that names a library's shared frame and no addon, no event and no
cause. `[sys-timing]` saw the same cost as `ui_quest::feed_quest` at 85.7 ms for
one run in 76, because every handler runs synchronously inside whichever system
fired, so the system holding the stack gets the bill.
Two conventions the report sticks to:
- `self` is nest-adjusted, in both columns. A handler's own time has any event it
fired taken back out (`event::fire` differences `event_prof::nested_ns` across
the call), or every event in a cascade reports the cascade and the row naming
the real cost is the one that looks innocent. `total` keeps it, which is what a
`[sys-timing]` span sees.
- A fire is one `fire_event`, however wide it fans out, because that is the unit
a dropped frame is measured in. `calls` is beside it for the width.
Measured on the player's own 92-addon interface (`tick_bench`'s new `[events]`
row, three fires per event from a settled start):
us/fire worst event
5068 14759 QUEST_DETAIL <- HCQuest.lua:139 took 14,097 us
764 1324 QUEST_LOG_UPDATE
662 1564 QUEST_FINISHED
Read `us/fire` against `worst` and that 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 paid per quest. With that read correctly, no quest event costs more
than ~1.5 ms recurring offline — so the bench does not reproduce the live 57-73
ms and says so, rather than offering a number that looks like an answer. Hence
the instrument, armed in `./measure.sh`.
Also adds `./measure.sh --frames`, which arms two meters that already existed and
have never been armed: `WOW_FRAME_PHASES=50` and `WOW_RENDER_MS=1`. A frame's
wall time is `max(main app, render app)` since bevy pipelines the render app onto
its own thread, so when the render app is the longer, `wall` climbs while `cpu`,
`main`, `gpu` and every per-system `worst` all read healthy — exactly what that
session's **161 ms frame in a second whose costliest system worst was 2.9 ms over
105 runs** looks like, and what 43 of its 64 spike-seconds look like. Its own
mode because both perturb what they measure.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn
This commit is contained in:
Claude Opus 5
@@ -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
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -0,0 +1,360 @@
|
||||
//! Per-event cost attribution (`WOW_UI_EVENTS=<secs>`): 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=<secs>`, read once; unparseable or non-positive is off.
|
||||
fn env_period() -> Option<f32> {
|
||||
static PERIOD: std::sync::OnceLock<Option<f32>> = std::sync::OnceLock::new();
|
||||
*PERIOD.get_or_init(|| {
|
||||
std::env::var("WOW_UI_EVENTS")
|
||||
.ok()
|
||||
.and_then(|v| v.parse::<f32>().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<u32>,
|
||||
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<u64>,
|
||||
/// 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<u32>, u64)>,
|
||||
rows: HashMap<String, Slot>,
|
||||
}
|
||||
|
||||
/// 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<Instant>,
|
||||
}
|
||||
|
||||
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::<EventProf>() {
|
||||
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::<EventProf>() 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::<EventProf>()
|
||||
.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::<EventProf>() 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<String>,
|
||||
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::<EventProf>() {
|
||||
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<EventRow> {
|
||||
// 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::<EventProf>() else {
|
||||
return Vec::new();
|
||||
};
|
||||
prof.rows
|
||||
.iter()
|
||||
.map(|(event, slot)| (event.clone(), slot.clone()))
|
||||
.collect()
|
||||
};
|
||||
let mut rows: Vec<EventRow> = 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::<EventProf>() {
|
||||
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::<EventProf>()
|
||||
.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 <frame> (<us>)`, 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);
|
||||
}
|
||||
}
|
||||
@@ -258,7 +258,7 @@ impl UiScript {
|
||||
impl UiScript {
|
||||
/// A row's label: the frame's name, else the handler's `<file>:<line>` (an unnamed frame is the
|
||||
/// common addon timer), else `#<id>`.
|
||||
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
|
||||
|
||||
@@ -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);
|
||||
|
||||
|
||||
@@ -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<EventRow> {
|
||||
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"
|
||||
);
|
||||
}
|
||||
@@ -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;
|
||||
|
||||
@@ -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<ScriptValue>) {
|
||||
let model_mut = || lua.app_data_mut::<Model>().expect("model app_data set");
|
||||
// `WOW_UI_EVENTS=<secs>`: 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=<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_EVENTS=<secs>`: 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=<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);
|
||||
|
||||
+29
-1
@@ -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" "$@"
|
||||
|
||||
Reference in New Issue
Block a user