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 56a6ffcc..8260f8a2 100644 --- a/crates/benilla-app/src/addon_harness/tick_bench_tests.rs +++ b/crates/benilla-app/src/addon_harness/tick_bench_tests.rs @@ -536,17 +536,29 @@ fn tick_bench() { rows.len(), total / 1000.0 / per ); - println!("[tick] self/f(us) total/f(us) calls/f handler"); + println!("[tick] self/f(us) total/f(us) calls/f worst(us) handler"); for r in rows.iter().take(15) { println!( - "[tick] {:11.1} {:12.1} {:8.2} {}:{}", + "[tick] {:11.1} {:12.1} {:8.2} {:11.1} {}:{}", r.self_us / per, r.total_us / per, f64::from(r.calls) / per, + r.worst_us, r.frame, r.script ); } + // A handler that stalls one frame in five hundred has a mean near zero and never reaches + // the table above, so the worst single call is ranked on its own. + let mut by_worst: Vec<&benilla_ui::script::HandlerRow> = rows.iter().collect(); + by_worst.sort_by(|a, b| b.worst_us.total_cmp(&a.worst_us)); + println!("[tick] {label} worst single call:"); + for r in by_worst.iter().take(8) { + println!( + "[tick] {:11.1} us once (self {:.1} us over {} calls) {}:{}", + r.worst_us, r.self_us, r.calls, r.frame, r.script + ); + } } // ── What one addon bug costs a frame ──────────────────────────────────────────────────── diff --git a/crates/benilla-ui/src/script/handler_prof.rs b/crates/benilla-ui/src/script/handler_prof.rs index e124a6d1..1b10c131 100644 --- a/crates/benilla-ui/src/script/handler_prof.rs +++ b/crates/benilla-ui/src/script/handler_prof.rs @@ -35,12 +35,22 @@ fn env_period() -> Option { }) } +/// A single call this slow is a dropped frame at any framerate a player plays at, so it is worth +/// naming on its own even when its mean is nothing. +const STALL_US: f64 = 2000.0; + +/// How many stalling handlers the report names. +const STALL_ROWS: usize = 8; + /// One `(frame, script)` pair's accumulation over the current window. struct Slot { script: String, calls: u32, total_ns: u64, self_ns: u64, + /// The costliest single call's self time. A handler that stalls a frame once every few + /// seconds is invisible in a mean over 500 frames, and a stall is what a player feels. + worst_ns: u64, } /// The profiler's state, one per VM, keyed by frame id: names resolve at report time, and a frame @@ -115,12 +125,14 @@ impl Drop for Fire<'_> { slot.calls += 1; slot.total_ns += total; slot.self_ns += self_ns; + slot.worst_ns = slot.worst_ns.max(self_ns); } None => slots.push(Slot { script: self.script.to_string(), calls: 1, total_ns: total, self_ns, + worst_ns: self_ns, }), } } @@ -137,6 +149,8 @@ pub struct HandlerRow { pub self_us: f64, /// Microseconds in this handler, including the handlers it fired. pub total_us: f64, + /// The costliest single call's self time, in microseconds. + pub worst_us: f64, } impl UiScript { @@ -162,33 +176,38 @@ impl UiScript { /// This VM's handler costs over the current window as totals, heaviest self time first. pub fn handler_profile(&self) -> Vec { // Snapshot, then release the borrow: labelling reaches into the model and back into Lua. - let raw: Vec<(u32, String, u32, u64, u64)> = match self.lua.app_data_ref::() { - Some(prof) => prof - .rows - .iter() - .flat_map(|(&id, slots)| { - slots.iter().map(move |slot| { - ( - id, - slot.script.clone(), - slot.calls, - slot.self_ns, - slot.total_ns, - ) + let raw: Vec<(u32, String, u32, u64, u64, u64)> = + match self.lua.app_data_ref::() { + Some(prof) => prof + .rows + .iter() + .flat_map(|(&id, slots)| { + slots.iter().map(move |slot| { + ( + id, + slot.script.clone(), + slot.calls, + slot.self_ns, + slot.total_ns, + slot.worst_ns, + ) + }) }) - }) - .collect(), - None => return Vec::new(), - }; + .collect(), + None => return Vec::new(), + }; let mut rows: Vec = raw .into_iter() - .map(|(id, script, calls, self_ns, total_ns)| HandlerRow { - frame: self.handler_label(id, &script), - script, - calls, - self_us: self_ns as f64 / 1000.0, - total_us: total_ns as f64 / 1000.0, - }) + .map( + |(id, script, calls, self_ns, total_ns, worst_ns)| HandlerRow { + frame: self.handler_label(id, &script), + script, + calls, + self_us: self_ns as f64 / 1000.0, + total_us: total_ns as f64 / 1000.0, + worst_us: worst_ns as f64 / 1000.0, + }, + ) .collect(); rows.sort_by(|a, b| { b.self_us @@ -287,13 +306,14 @@ fn print_report(rows: &[HandlerRow], window: f32, frames: u32, nested: u32) { total_self / per_frame, ); eprintln!("[ui-handlers] by script: {}", rollup.join(" ")); - eprintln!("[ui-handlers] self/f total/f calls/f handler"); + eprintln!("[ui-handlers] self/f total/f calls/f worst handler"); for row in rows.iter().take(REPORT_ROWS) { eprintln!( - "[ui-handlers] {:8.1} {:8.1} {:8.2} {}:{}", + "[ui-handlers] {:8.1} {:8.1} {:8.2} {:8.1} {}:{}", row.self_us / per_frame, row.total_us / per_frame, f64::from(row.calls) / per_frame, + row.worst_us, row.frame, row.script, ); @@ -301,10 +321,36 @@ fn print_report(rows: &[HandlerRow], window: f32, frames: u32, nested: u32) { if let Some(rest) = rows.len().checked_sub(REPORT_ROWS).filter(|n| *n > 0) { let tail: f64 = rows.iter().skip(REPORT_ROWS).map(|r| r.self_us).sum(); eprintln!( - "[ui-handlers] {:8.1} … {rest} more", + "[ui-handlers] {:8.1} … {rest} more", tail / per_frame ); } + print_stalls(rows); +} + +/// The handlers whose worst single call cost a frame, which the table above cannot show: it ranks +/// by the mean, and a handler that stalls once in five hundred frames has a mean near zero. Only +/// the ones the table left out, so the block says something new or nothing. +fn print_stalls(rows: &[HandlerRow]) { + let mut worst: Vec<&HandlerRow> = rows + .iter() + .skip(REPORT_ROWS) + .filter(|r| r.worst_us >= STALL_US) + .collect(); + if worst.is_empty() { + return; + } + worst.sort_by(|a, b| b.worst_us.total_cmp(&a.worst_us)); + eprintln!( + "[ui-handlers] worst single call, among the {} not listed above:", + rows.len() - REPORT_ROWS + ); + for row in worst.iter().take(STALL_ROWS) { + eprintln!( + "[ui-handlers] {:8.1} us once (self {:.1} us over {} calls) {}:{}", + row.worst_us, row.self_us, row.calls, row.frame, row.script, + ); + } } /// Install the profiler's `app_data` slot, armed from the environment. Unconditional: mlua refuses diff --git a/crates/benilla-ui/src/script/tests/handler_prof.rs b/crates/benilla-ui/src/script/tests/handler_prof.rs index 3e741447..3100e744 100644 --- a/crates/benilla-ui/src/script/tests/handler_prof.rs +++ b/crates/benilla-ui/src/script/tests/handler_prof.rs @@ -197,3 +197,54 @@ fn disarming_clears_the_window() { "and a disarmed VM keeps recording nothing" ); } + +/// The column the mean cannot show: a handler that stalls one frame in ten ranks below a steadier +/// one by self time and still has the larger worst call. The two bodies differ by 3x in work per +/// the ratio below, which is the margin the ordering rests on — not an absolute duration. +#[test] +fn the_worst_call_is_one_calls_cost_and_not_the_mean() { + let mut s = armed(); + s.run( + r#" + local function burn(n) local x = 0 for i = 1, n do x = x + i end return x end + -- 10 calls of 50k: the larger self time, the smaller single call. + local steady = CreateFrame("Frame", "Steady") + steady:SetScript("OnUpdate", function() burn(50000) end) + -- One call of 150k, on the first tick only: the smaller self time, the larger single call. + local spiky = CreateFrame("Frame", "Spiky") + spiky:SetScript("OnUpdate", function() + if not this.done then this.done = true burn(150000) end + end) + "#, + ) + .unwrap(); + for _ in 0..10 { + s.tick(0.016); + } + assert!(s.errors().is_empty(), "{:?}", s.errors()); + + let rows = s.handler_profile(); + let steady = row(&rows, "Steady", "OnUpdate").expect("the steady handler"); + let spiky = row(&rows, "Spiky", "OnUpdate").expect("the spiky handler"); + assert_eq!((steady.calls, spiky.calls), (10, 10)); + assert!( + steady.self_us > spiky.self_us, + "the steady handler costs more over the window, so it ranks first: {rows:#?}" + ); + assert!( + spiky.worst_us > steady.worst_us, + "and the spiky one's single call is the worse stall, which is the whole point of the \ + column: {rows:#?}" + ); + assert!( + spiky.worst_us <= spiky.self_us, + "one call cannot cost more than every call" + ); + let spiky_mean = spiky.self_us / f64::from(spiky.calls); + assert!( + spiky.worst_us > spiky_mean * 2.0, + "nine of its ten calls do nothing, so the mean hides the stall by about tenfold: \ + worst {:.1} us against a mean of {spiky_mean:.1} us", + spiky.worst_us + ); +} diff --git a/measure.sh b/measure.sh new file mode 100755 index 00000000..08f497d8 --- /dev/null +++ b/measure.sh @@ -0,0 +1,41 @@ +#!/usr/bin/env bash +# Launch benilla with the measurement instruments armed, so a play-test answers "where did the +# frame go?" instead of only "it felt slow". +# +# ./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 +# +# 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 +# beside the errors. +# +# Why a script and not a line of environment variables: the set is long, and a run with one of +# them missing looks exactly like a run that found nothing. This prints what it armed. +set -euo pipefail +root="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" + +# Per-system milliseconds once a second, and the stall watchdog that names a system still running +# after WOW_STALL_MS. This is the one that says whether a frame went to the UI or the world. +export WOW_SYSTEM_TIMING=1 +# The UI tick, split into its eleven engine phases, with `C_Timer` fires credited to the line that +# armed them. +export WOW_UI_TICK=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 +# The frame's own cost, split main thread against GPU, so a dip says which side it is on. +export WOW_FLASH_TRACE=1 +export WOW_GPU_MS=1 + +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 + # `benilla-ui/src/script/verb_prof.rs`). + export WOW_UI_VERBS=5 + shift +fi + +echo "measure: armed —" +env | grep -E '^WOW_(SYSTEM_TIMING|UI_TICK|UI_HANDLERS|UI_VERBS|FLASH_TRACE|GPU_MS)=' | sort | sed 's/^/ /' +exec "$root/run.sh" "$@"