gromandClaude Opus 5
e269e4dbb4
`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
76 lines
4.3 KiB
Bash
Executable File
76 lines
4.3 KiB
Bash
Executable File
#!/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
|
|
# ./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
|
|
# 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 *pass*, split into its phases: tick, the FontString measure round-trip and layout
|
|
# resolve, extract, convert, the mesh rebuild. The one that distinguishes "the addons are slow"
|
|
# from "the layout is resolving a dirty graph", which the tick split below cannot see — the first
|
|
# session with this armed found 11.7 ms a frame outside the tick in a run whose handler profile was
|
|
# clean.
|
|
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
|
|
# 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:-}" = "--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
|
|
# `benilla-ui/src/script/verb_prof.rs`).
|
|
export WOW_UI_VERBS=5
|
|
shift
|
|
fi
|
|
|
|
echo "measure: armed —"
|
|
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" "$@"
|