`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
379 lines
16 KiB
Rust
379 lines
16 KiB
Rust
//! Handler firing: the FrameScript calling convention for events, ticks and show/hide. The
|
|
//! reference sets `this` (`0x872e64`), `event` (`0x84b648`) and `arg1..argN` (`0x8722dc`) around
|
|
//! the call, restoring each after, and `pcall`s with no arguments; the handler here also gets the
|
|
//! same values as `(self, event, ...)` arguments, which 1.12 does not pass.
|
|
//! Handler errors return to the caller, which records them in [`super::Model::errors`].
|
|
|
|
use std::borrow::Cow;
|
|
|
|
use mlua::{Function, Lua, Table, Value};
|
|
|
|
use super::{Model, ScriptValue, REG_SCRIPTS};
|
|
use crate::script::object::frame_wrapper;
|
|
use crate::widget::{ButtonState, FrameHandle};
|
|
|
|
/// `UiScript::fire_event` for engine code that holds only the Lua context.
|
|
pub(super) fn fire_global(lua: &Lua, event: &str, args: &[ScriptValue]) {
|
|
super::tick::fire_event_into(lua, event, args.to_vec());
|
|
}
|
|
|
|
/// The `RegisterAllEvents()` half of a dispatch: the all-events frames, after the event's own
|
|
/// listeners and skipping any already visited. The next frame is re-found by position each step
|
|
/// (`0x703ee8`), so a handler that unregisters the walk's successor ends the dispatch there.
|
|
pub(super) fn fire_all_event_listeners(lua: &Lua, event: &str, args: &[ScriptValue]) {
|
|
let model_mut = || lua.app_data_mut::<Model>().expect("model app_data set");
|
|
let mut at = model_mut().all_event_frames.first().copied();
|
|
while let Some(h) = at {
|
|
let mut model = model_mut();
|
|
let Some(pos) = model.all_event_frames.iter().position(|&x| x == h) else {
|
|
break;
|
|
};
|
|
let next = model.all_event_frames.get(pos + 1).copied();
|
|
let already = model
|
|
.event_to_frames
|
|
.get(event)
|
|
.is_some_and(|l| l.contains(&h));
|
|
let id = model.frame_id(h);
|
|
drop(model);
|
|
if !already {
|
|
if let Err(e) = fire_event_handler(lua, id, event, args) {
|
|
lua.app_data_mut::<Model>()
|
|
.expect("model app_data")
|
|
.record_script_error(e.to_string());
|
|
}
|
|
}
|
|
at = next;
|
|
}
|
|
}
|
|
|
|
/// Fire a frame's `OnEvent` (both conventions) with the given args.
|
|
pub(super) fn fire_event_handler(
|
|
lua: &Lua,
|
|
id: u32,
|
|
event: &str,
|
|
args: &[ScriptValue],
|
|
) -> mlua::Result<()> {
|
|
let extra: Vec<Value> = args
|
|
.iter()
|
|
.cloned()
|
|
.map(|a| a.into_lua(lua))
|
|
.collect::<mlua::Result<_>>()?;
|
|
fire(lua, id, "OnEvent", Some(event), extra)
|
|
}
|
|
|
|
/// Fire a frame's `OnUpdate` with `arg1 = elapsed`.
|
|
pub(super) fn fire_update_handler(lua: &Lua, id: u32, elapsed: f32) -> mlua::Result<()> {
|
|
fire(
|
|
lua,
|
|
id,
|
|
"OnUpdate",
|
|
None,
|
|
vec![Value::Number(f64::from(elapsed))],
|
|
)
|
|
}
|
|
|
|
/// Fire a handler that carries no `event` name (`OnEnter`, `OnClick`, `OnValueChanged`, ...), with
|
|
/// `extra` as its `arg1..argN`; a no-op when the frame has no such script.
|
|
pub(super) fn fire_widget_handler(
|
|
lua: &Lua,
|
|
id: u32,
|
|
script: &str,
|
|
extra: Vec<Value>,
|
|
) -> mlua::Result<()> {
|
|
fire(lua, id, script, None, extra)
|
|
}
|
|
|
|
/// Drain [`Model::pending_size_changed`], queued by the resolve pass, and fire `OnSizeChanged` for
|
|
/// each, recording errors. It drains once: a size a handler changes fires on the next resolve, as
|
|
/// the reference's `ApplyRect` does, so a handler that grows its own frame cannot spin forever.
|
|
pub(super) fn fire_size_changes(lua: &Lua) {
|
|
let pending = std::mem::take(
|
|
&mut lua
|
|
.app_data_mut::<Model>()
|
|
.expect("model")
|
|
.pending_size_changed,
|
|
);
|
|
for (id, w, h) in pending {
|
|
if let Err(e) = fire(
|
|
lua,
|
|
id,
|
|
"OnSizeChanged",
|
|
None,
|
|
vec![Value::Number(f64::from(w)), Value::Number(f64::from(h))],
|
|
) {
|
|
lua.app_data_mut::<Model>()
|
|
.expect("model")
|
|
.record_script_error(e.to_string());
|
|
}
|
|
}
|
|
}
|
|
|
|
/// Fire `OnShow`/`OnHide` for the frames whose effective visibility just changed, recording
|
|
/// errors in [`Model::errors`]. A shown `toplevel` frame raises here, after the subtree has
|
|
/// propagated and before its `OnShow` (`0x76ae10` at `0x76aee0`), so a show that does not come
|
|
/// through Lua `Show` raises too.
|
|
pub(super) fn fire_visibility_changes(lua: &Lua, changed: Vec<FrameHandle>) {
|
|
// Resolve (handle, id, now-visible?) under one short borrow, then fire with no borrow held.
|
|
let items: Vec<(FrameHandle, u32, bool)> = {
|
|
let mut model = lua.app_data_mut::<Model>().expect("model");
|
|
changed
|
|
.into_iter()
|
|
.filter_map(|h| {
|
|
let vis = model.arena.frame(h)?.effective_visible;
|
|
Some((h, model.frame_id(h), vis))
|
|
})
|
|
.collect()
|
|
};
|
|
// Hiding the hovered frame, directly or by an ancestor, fires its `OnLeave` inside the hide and
|
|
// before its `OnHide` (`0x764ba0`'s tail in `0x76ad50`, the leave at `0x764cce`), clears the
|
|
// hover and the drag-arm (`+0x100`/`+0x104`) and arms the re-pick; a show arms it too
|
|
// (`0x764b8d`). This leave is how a tooltip closes with its window; the reference has no other.
|
|
let left: Option<(FrameHandle, u32)> = {
|
|
let mut model = lua.app_data_mut::<Model>().expect("model");
|
|
let hidden_hover = model
|
|
.mouseover
|
|
.filter(|&m| items.iter().any(|&(h, _, vis)| h == m && !vis));
|
|
// The leave is a virtual call (`0x764cce`, `[vtable+0x50]`): a disabled Button's own
|
|
// `0x7794e0` skips its `OnLeave`, while the hover and the drag-arm still clear.
|
|
let notified = super::button::hover_notify_runs(&model, hidden_hover);
|
|
if let Some(m) = hidden_hover {
|
|
model.mouseover = None;
|
|
if model.drag.as_ref().is_some_and(|d| d.source == m) {
|
|
model.drag = None;
|
|
}
|
|
}
|
|
model.hover_repick |= hidden_hover.is_some() || items.iter().any(|&(_, _, vis)| vis);
|
|
hidden_hover
|
|
.filter(|_| notified)
|
|
.map(|m| (m, model.frame_id(m)))
|
|
};
|
|
if let Some((_, oid)) = left {
|
|
if let Err(e) = fire_widget_handler(lua, oid, "OnLeave", vec![Value::Boolean(true)]) {
|
|
lua.app_data_mut::<Model>()
|
|
.expect("model")
|
|
.record_script_error(e.to_string());
|
|
}
|
|
}
|
|
for (h, id, visible) in items {
|
|
if visible {
|
|
let mut model = lua.app_data_mut::<Model>().expect("model");
|
|
super::object::toplevel::raise_on_show(&mut model, h);
|
|
} else {
|
|
// `CSimpleButton`'s hide notify (`+0x34`, `0x7791e0`) un-presses it, unless disabled
|
|
// or locked, before the base notify, so a button hidden while held comes back unpushed.
|
|
let mut model = lua.app_data_mut::<Model>().expect("model");
|
|
super::button::edge(&mut model, h, ButtonState::on_hide);
|
|
}
|
|
let name = if visible { "OnShow" } else { "OnHide" };
|
|
if let Err(e) = fire(lua, id, name, None, Vec::new()) {
|
|
lua.app_data_mut::<Model>()
|
|
.expect("model")
|
|
.record_script_error(e.to_string());
|
|
}
|
|
// The EditBox show/hide overrides (`0x81c910` `+0x30`/`+0x34`) call the base notify first,
|
|
// so this runs after the `fire`: an `autoFocus` box takes a free focus, a hidden box
|
|
// releases its own.
|
|
super::editbox::visibility_focus(lua, h, visible);
|
|
}
|
|
}
|
|
|
|
/// Whether a handler is bound under `script`, without firing it: the keyboard walk consumes on
|
|
/// the slot's presence (`0x76b7d0`). A failed lookup reads absent, so the gate never raises.
|
|
pub(super) fn has_widget_handler(lua: &Lua, id: u32, script: &str) -> bool {
|
|
let Ok(scripts) = lua.named_registry_value::<Table>(REG_SCRIPTS) else {
|
|
return false;
|
|
};
|
|
match scripts.get::<Value>(id) {
|
|
Ok(Value::Table(per)) => matches!(per.get::<Value>(script), Ok(Value::Function(_))),
|
|
_ => false,
|
|
}
|
|
}
|
|
|
|
/// The Lua half of [`protected_call`]: a reusable `xpcall` trampoline, built once per VM and kept
|
|
/// in the registry under [`super::REG_PROTECTED_CALL`].
|
|
///
|
|
/// **Why a handler is not simply called through mlua.** `Function::call` installs mlua's own
|
|
/// message handler (`mlua-sys` `lua51/compat.rs:457` `luaL_traceback`), which for *every* stack
|
|
/// level asks `compat53_pushfuncname` for a name, and that searches the global table and then one
|
|
/// level into every table in it (`compat.rs:73-119` `compat53_findfield`). On this install that is
|
|
/// 27,109 globals plus 83,337 keys one level in, **per level, per raise**: measured at 6.3 ms a
|
|
/// raise with the shipped addons loaded, against 0.6 us for Lua's own `pcall`
|
|
/// (`addon_harness::tick_bench`). One addon bug in an `OnUpdate` or a `C_Timer` ticker therefore
|
|
/// cost milliseconds of every frame it fired on, and the cost grew with the Lua heap — pfQuest's
|
|
/// databases are 129 MB of the 154 MB this install carries. Lua's own `xpcall` has no such search,
|
|
/// and 1.12's FrameScript dispatch is a plain `lua_pcall` anyway (`0x704d50`).
|
|
///
|
|
/// The arguments go through a reused table rather than Lua varargs because `xpcall` cannot pass
|
|
/// any (5.0 and 5.1 alike) and a per-fire closure would be garbage on every handler of every
|
|
/// frame. One shared table is re-entrancy-safe: `run` reads it only to *start* the call, so a
|
|
/// nested fire that rewrites it cannot disturb a call already running.
|
|
///
|
|
/// A raise's message keeps the shape the host already logs — the message, then a `stack traceback:`
|
|
/// block — built from `debugstack`, the reference's own walk (`0x703760`), which names frames from
|
|
/// `lua_getinfo` alone and searches no table. A host-side error arrives as a userdata and is handed
|
|
/// back untouched, exactly as mlua's handler also leaves it, so `Usage:` and the instruction-budget
|
|
/// raise read as they did.
|
|
const PROTECTED_CALL: &str = r#"
|
|
local xpcall, unpack, tostring, type = xpcall, unpack, tostring, type
|
|
local debugstack, gsub = debugstack, string.gsub
|
|
-- `f`, `n` and `1..n` are written by `protected_call` just before `call`.
|
|
local args = {}
|
|
local function run() return args.f(unpack(args, 1, args.n)) end
|
|
local function onerror(e)
|
|
-- A host error object: mlua formats it itself, and its own handler adds no traceback to one
|
|
-- either, so neither does this.
|
|
if type(e) == "userdata" then return e end
|
|
-- Level 3 skips `debugstack`, `onerror` and `run`, so frame 1 is the line that raised.
|
|
-- `debugstack` writes 5.0's ``in function `name'``; the `'name'` spelling here is the one
|
|
-- mlua's traceback used, which `addon_harness::normalise_error` reads.
|
|
local trace = gsub(gsub(debugstack(3) or "", "`([^']*)'", "'%1'"), "\n", "\n\t")
|
|
return tostring(e) .. "\nstack traceback:\n\t" .. trace
|
|
end
|
|
local function call()
|
|
local ok, err = xpcall(run, onerror)
|
|
-- The function reference goes; the argument slots are overwritten by the next fire, as the
|
|
-- `this`/`arg1` globals this convention saves and restores already are.
|
|
args.f = nil
|
|
if ok then return nil end
|
|
return err
|
|
end
|
|
return { call = call, args = args }
|
|
"#;
|
|
|
|
/// Build the `xpcall` trampoline this VM's handler dispatch calls through.
|
|
pub(super) fn install(lua: &Lua) -> mlua::Result<()> {
|
|
let slot: Table = lua
|
|
.load(PROTECTED_CALL)
|
|
.set_name("=[benilla protected call]")
|
|
.set_mode(mlua::ChunkMode::Text)
|
|
.eval()?;
|
|
lua.set_named_registry_value(super::REG_PROTECTED_CALL, slot)
|
|
}
|
|
|
|
/// Call `func` with `args`, protected on the **Lua** side rather than mlua's: see
|
|
/// [`PROTECTED_CALL`] for why that distinction is worth milliseconds a raise.
|
|
///
|
|
/// The returned error is the one the caller would have got before: a Lua raise as
|
|
/// `RuntimeError(message + traceback)`, a host raise as itself.
|
|
pub(crate) fn protected_call(lua: &Lua, func: &Function, args: &[Value]) -> mlua::Result<()> {
|
|
let slot: Table = lua.named_registry_value(super::REG_PROTECTED_CALL)?;
|
|
let store: Table = slot.raw_get("args")?;
|
|
store.raw_set("f", func.clone())?;
|
|
store.raw_set("n", args.len())?;
|
|
for (i, v) in args.iter().enumerate() {
|
|
store.raw_set(i + 1, v.clone())?;
|
|
}
|
|
let call: Function = slot.raw_get("call")?;
|
|
match call.call::<Value>(())? {
|
|
Value::Nil => Ok(()),
|
|
Value::String(s) => Err(mlua::Error::RuntimeError(s.to_string_lossy())),
|
|
// A host error the trampoline handed back: mlua pops a wrapped failure as `Value::Error`.
|
|
Value::Error(e) => Err(*e),
|
|
other => Err(mlua::Error::RuntimeError(format!("{other:?}"))),
|
|
}
|
|
}
|
|
|
|
/// The one firing path: `event_name` is `OnEvent`'s, `extra` the `arg1..argN`. Holds no model
|
|
/// borrow across the call.
|
|
fn fire(
|
|
lua: &Lua,
|
|
id: u32,
|
|
script: &str,
|
|
event_name: Option<&str>,
|
|
extra: Vec<Value>,
|
|
) -> mlua::Result<()> {
|
|
let scripts: Table = lua.named_registry_value(REG_SCRIPTS)?;
|
|
let func: Function = match scripts.get::<Value>(id)? {
|
|
Value::Table(per) => match per.get::<Value>(script)? {
|
|
Value::Function(f) => f,
|
|
_ => return Ok(()),
|
|
},
|
|
_ => return Ok(()),
|
|
};
|
|
|
|
let wrapper = frame_wrapper(lua, id)?;
|
|
// The profiler's fire opens after `frame_wrapper`, where no model borrow is held, and closes
|
|
// when the guard drops, unwinds included.
|
|
let _fire =
|
|
super::handler_prof::armed().then(|| super::handler_prof::Fire::open(lua, id, script));
|
|
// `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.
|
|
const ARG_NAMES: [&str; 16] = [
|
|
"arg1", "arg2", "arg3", "arg4", "arg5", "arg6", "arg7", "arg8", "arg9", "arg10", "arg11",
|
|
"arg12", "arg13", "arg14", "arg15", "arg16",
|
|
];
|
|
|
|
/// The global name for arg `i`, 1-based like the globals.
|
|
fn arg_name(i: usize) -> Cow<'static, str> {
|
|
match ARG_NAMES.get(i - 1) {
|
|
Some(&name) => Cow::Borrowed(name),
|
|
None => Cow::Owned(format!("arg{i}")),
|
|
}
|
|
}
|
|
|
|
/// The calling convention, shared by [`fire`] and the loader's `OnLoad`: sets `this`, `event` and
|
|
/// `arg1..argN`, passes `(self[, event], extra...)`, and restores the globals after the call, even
|
|
/// on error, so nested fires are safe.
|
|
pub(crate) fn invoke_with_globals(
|
|
lua: &Lua,
|
|
wrapper: Table,
|
|
func: &Function,
|
|
event_name: Option<&str>,
|
|
extra: Vec<Value>,
|
|
) -> mlua::Result<()> {
|
|
let g = lua.globals();
|
|
|
|
let saved_this: Value = g.get("this")?;
|
|
let saved_event: Value = g.get("event")?;
|
|
let n = extra.len();
|
|
let mut saved_args: Vec<Value> = Vec::with_capacity(n);
|
|
for i in 1..=n {
|
|
saved_args.push(g.get::<Value>(arg_name(i).as_ref())?);
|
|
}
|
|
|
|
g.set("this", wrapper.clone())?;
|
|
if let Some(ev) = event_name {
|
|
g.set("event", lua.create_string(ev)?)?;
|
|
}
|
|
for (i, v) in extra.iter().enumerate() {
|
|
g.set(arg_name(i + 1).as_ref(), v.clone())?;
|
|
}
|
|
|
|
let mut modern: Vec<Value> = Vec::with_capacity(2 + n);
|
|
modern.push(Value::Table(wrapper));
|
|
if let Some(ev) = event_name {
|
|
modern.push(Value::String(lua.create_string(ev)?));
|
|
}
|
|
modern.extend(extra.iter().cloned());
|
|
|
|
// A protected call; the globals are restored before its outcome returns. Through Lua's own
|
|
// `xpcall` ([`protected_call`]), never mlua's, whose message handler walks the whole global
|
|
// table looking for a name for each stack level.
|
|
let outcome = protected_call(lua, func, &modern);
|
|
|
|
g.set("this", saved_this)?;
|
|
g.set("event", saved_event)?;
|
|
for (i, v) in saved_args.into_iter().enumerate() {
|
|
g.set(arg_name(i + 1).as_ref(), v)?;
|
|
}
|
|
|
|
outcome
|
|
}
|