From a51f29b9d3a38420f40f3bfbe7b4f7cb31c8b13e Mon Sep 17 00:00:00 2001 From: Sam Date: Thu, 20 Aug 2026 19:07:34 +0700 Subject: [PATCH] the perf pill leaves egui, and the field store goes flat MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - the perf pill is ~25 quads on the player-UI pass — `{fps} fps {cpu} ms` and nothing else — so the egui lane sleeps whenever no dev panel is open, instead of the collapsed pill paying ~1 ms for egui's whole per-frame train - the pill is the whole HUD: the expanded readout, the spike arrow and the spike-detection engine behind it are removed; a >250 ms hitch still logs - WOW_CPU_CENSUS=: — a per-thread CPU census that sums to the process total exactly, user/sys split; in Lower Blackrock Spire the main thread is ~41% of ~14.5 ms, the render thread ~17%, the compute pool ~25%, Metal's own workers ~12% - the object field store goes flat: the wire's presence mask plus a dense value array replace a BTreeMap, so 5–10k descriptor probes a frame are two array indexings — the main thread ~0.5 ms/frame lighter at the same pin Co-Authored-By: Claude Fable 5 --- crates/benilla-app/src/debug_panel/mod.rs | 6 +- crates/benilla-app/src/perf/census.rs | 258 +++++++ crates/benilla-app/src/perf/hud.rs | 724 ++++-------------- crates/benilla-app/src/perf/mod.rs | 76 +- crates/benilla-app/src/perf/stats.rs | 694 ++--------------- .../src/messages/update_object/fields/mod.rs | 98 ++- .../messages/update_object/fields/player.rs | 11 +- 7 files changed, 561 insertions(+), 1306 deletions(-) diff --git a/crates/benilla-app/src/debug_panel/mod.rs b/crates/benilla-app/src/debug_panel/mod.rs index 4846d35f..23d7d887 100644 --- a/crates/benilla-app/src/debug_panel/mod.rs +++ b/crates/benilla-app/src/debug_panel/mod.rs @@ -282,7 +282,8 @@ fn spawn_egui_camera(mut commands: Commands) { } /// Demand-gate the whole egui lane (decision 1445): when no dev overlay is open — panel closed, -/// perf HUD hidden (chord+`P`), inspect off — the primary context goes `run_manually` (which +/// inspect off (the perf HUD's pill is quads on the player-UI pass and never needs this lane; +/// 1453/1454) — the primary context goes `run_manually` (which /// `bevy_egui`'s context-pass loop honors by skipping it outright: no begin/end pass, no /// tessellate, no `EguiPrimaryContextPass` run) and the overlay camera sleeps (no Core2d graph /// run, no composite, no render-side prep). A hidden dev surface then costs what a player build @@ -293,12 +294,11 @@ fn spawn_egui_camera(mut commands: Commands) { /// the gated pass and would hold the last hover forever. fn gate_egui_lane( debug: Res, - hud: Res, inspect: Res, mut cams: Query<(&mut Camera, &mut EguiContextSettings), With>, mut over: ResMut, ) { - let open = debug.open || hud.visible || inspect.enabled; + let open = debug.open || inspect.enabled; for (mut cam, mut settings) in &mut cams { if cam.is_active != open { cam.is_active = open; diff --git a/crates/benilla-app/src/perf/census.rs b/crates/benilla-app/src/perf/census.rs index b1ec44d1..d1ee902d 100644 --- a/crates/benilla-app/src/perf/census.rs +++ b/crates/benilla-app/src/perf/census.rs @@ -3,6 +3,264 @@ use bevy::prelude::*; +/// `WOW_CPU_CENSUS=:` — the per-thread CPU census (macOS): where does the pill's +/// cpu-ms actually go, thread by thread, summing **exactly** to the process total? +/// +/// Two snapshots bracket a window: at each, `getrusage(RUSAGE_SELF)` (the pill's own clock, +/// [`super::clock::process_cpu_secs`]) and then every live thread's cumulative CPU via +/// `proc_pidinfo(PROC_PIDLISTTHREADS / PROC_PIDTHREADINFO)`. The report prints each thread's +/// delta over the window in ms/frame, then the **residual** = process delta − Σ live-thread +/// deltas, which is exactly the CPU of threads that exited inside the window (plus the +/// inter-read skew of the sweep itself). Nothing is modeled: every row is a measured delta and +/// the rows plus the residual reproduce the process total by construction. +/// +/// Facts this rests on, pinned empirically on this machine (2026-08-20, threadcpu.c probe) +/// before this was written: +/// - `pth_user_time`/`pth_system_time` are **nanoseconds** (a 200 ms calibrated burn read +/// 196.6 ms; the mach-timebase interpretation read 31.8× over) — *not* mach ticks, unlike +/// `rusage_info`'s `ri_user_time`. +/// - live-thread sums + exited-thread time = `getrusage` total to 0.05 ms over a ~1 s burn +/// (a thread that burned 250 ms and exited was absent from the list and present in the +/// residual at exactly 250.0 ms). +/// - `PROC_PIDLISTTHREADS = 6` (verified in the SDK's `sys/proc_info.h`; libc lacks the const). +#[cfg(target_os = "macos")] +pub(super) mod cpu_census { + use std::collections::HashMap; + + use bevy::prelude::*; + use bevy::time::Real; + + use crate::perf::clock::process_cpu_secs; + + /// `sys/proc_info.h`; not in the libc crate (its sibling `PROC_PIDTHREADINFO = 5` is). + const PROC_PIDLISTTHREADS: libc::c_int = 6; + + /// One cumulative reading per live thread: `tid → (name, user_ns, system_ns)`. User and + /// system are kept apart on purpose: real work is user time, while a thread whose CPU is + /// mostly *system* time is burning it in the kernel — park/wake churn, semaphores, mach + /// calls — which points at the scheduler/driver seam rather than at any system's body. + fn thread_snapshot() -> HashMap { + let pid = std::process::id() as libc::c_int; + let mut tids = [0u64; 512]; + // SAFETY: proc_pidinfo writes at most `buffersize` bytes into the buffer and returns + // how many it wrote; the buffer is a plain u64 array. + let n = unsafe { + libc::proc_pidinfo( + pid, + PROC_PIDLISTTHREADS, + 0, + tids.as_mut_ptr().cast(), + std::mem::size_of_val(&tids) as libc::c_int, + ) + }; + if n <= 0 { + return HashMap::new(); + } + let count = n as usize / std::mem::size_of::(); + let mut out = HashMap::with_capacity(count); + for &tid in &tids[..count] { + // SAFETY: zeroed is a valid proc_threadinfo (plain integers + a char array); + // proc_pidinfo fills it and returns the size written. + let mut ti: libc::proc_threadinfo = unsafe { std::mem::zeroed() }; + let r = unsafe { + libc::proc_pidinfo( + pid, + libc::PROC_PIDTHREADINFO, + tid, + (&raw mut ti).cast(), + std::mem::size_of::() as libc::c_int, + ) + }; + if r as usize != std::mem::size_of::() { + continue; // the thread died mid-sweep: its time lands in the residual + } + let name_bytes: Vec = ti + .pth_name + .iter() + .take_while(|&&c| c != 0) + .map(|&c| c as u8) + .collect(); + let name = String::from_utf8_lossy(&name_bytes).into_owned(); + out.insert(tid, (name, ti.pth_user_time, ti.pth_system_time)); + } + out + } + + struct Snap { + t: f32, + frames: u64, + process_secs: f64, + threads: HashMap, + } + + /// Armed from the env at plugin build (on the main thread — which is how `main_tid` is + /// known without pinning the census system itself). + #[derive(Resource)] + pub(in crate::perf) struct CpuCensus { + at: f32, + window: f32, + main_tid: u64, + frames: u64, + start: Option, + /// Every thread seen by the once-a-second sweeps inside the window, with its **latest** + /// cumulative reading — so a thread that dies mid-window can still be *named* in the + /// residual report (its last reading is a lower bound on what it contributed). + seen: HashMap, + next_sweep: f32, + done: bool, + } + + impl CpuCensus { + /// Parse `WOW_CPU_CENSUS=:`. Must be called on the main thread. + pub(in crate::perf) fn from_env() -> Option { + let v = std::env::var("WOW_CPU_CENSUS").ok()?; + let (at, window) = v.split_once(':')?; + let mut main_tid = 0u64; + // SAFETY: null pthread = the calling thread; writes one u64. + unsafe { libc::pthread_threadid_np(0, &mut main_tid) }; + Some(Self { + at: at.parse().ok()?, + window: window.parse().ok()?, + main_tid, + frames: 0, + start: None, + seen: HashMap::new(), + next_sweep: 0.0, + done: false, + }) + } + } + + pub(in crate::perf) fn cpu_census(mut census: ResMut, time: Res>) { + if census.done { + return; + } + census.frames += 1; + let now = time.elapsed_secs(); + if census.start.is_none() { + if now >= census.at { + census.start = Some(Snap { + t: now, + frames: census.frames, + process_secs: process_cpu_secs().unwrap_or(0.0), + threads: thread_snapshot(), + }); + } + return; + } + if now >= census.next_sweep { + census.next_sweep = now + 1.0; + for (tid, entry) in thread_snapshot() { + census.seen.insert(tid, entry); + } + } + let start = census.start.as_ref().unwrap(); + if now - start.t < census.window { + return; + } + let end_process = process_cpu_secs().unwrap_or(0.0); + let end_threads = thread_snapshot(); + let frames = (census.frames - start.frames).max(1); + let dt = now - start.t; + let process_ms = (end_process - start.process_secs) * 1000.0; + let per_frame = |ms: f64| ms / frames as f64; + + // Per-thread deltas over the window. A thread born inside the window has no start + // reading — its full cumulative time is its delta (it was zero at birth). + let mut rows: Vec<(f64, f64, String)> = Vec::new(); // (user_ms, sys_ms, label) + let mut live_sum_ms = 0.0f64; + for (tid, (name, end_u, end_s)) in &end_threads { + let (start_u, start_s) = start.threads.get(tid).map_or((0, 0), |(_, u, s)| (*u, *s)); + let user_ms = end_u.saturating_sub(start_u) as f64 / 1e6; + let sys_ms = end_s.saturating_sub(start_s) as f64 / 1e6; + live_sum_ms += user_ms + sys_ms; + // Hex tids so a row can be matched against `/usr/bin/sample`'s "Thread 0x…" headers. + let label = if *tid == census.main_tid { + format!("main (tid 0x{tid:x})") + } else if name.is_empty() { + format!("(unnamed tid 0x{tid:x})") + } else { + format!("{name} (tid 0x{tid:x})") + }; + rows.push((user_ms, sys_ms, label)); + } + rows.sort_by(|a, b| (b.0 + b.1).total_cmp(&(a.0 + a.1))); + let residual_ms = process_ms - live_sum_ms; + + eprintln!( + "[cpu-census] window {dt:.2} s, {frames} frames ({:.1} fps), process {process_ms:.1} ms \ + = {:.4} ms/frame (the pill's number over this window)", + frames as f32 / dt, + per_frame(process_ms), + ); + eprintln!( + "[cpu-census] {:>9} {:>8} {:>8} {:>6} thread", + "ms/frame", "user", "sys", "share" + ); + for (u, s, label) in &rows { + let ms = u + s; + if per_frame(ms) < 0.0005 { + continue; // folded into the "under" line below — still in the printed sum + } + eprintln!( + "[cpu-census] {:>9.4} {:>8.4} {:>8.4} {:>5.1}% {label}", + per_frame(ms), + per_frame(*u), + per_frame(*s), + ms / process_ms * 100.0 + ); + } + let tiny: f64 = rows + .iter() + .filter(|(u, s, _)| per_frame(u + s) < 0.0005) + .map(|(u, s, _)| u + s) + .sum(); + let tiny_n = rows + .iter() + .filter(|(u, s, _)| per_frame(u + s) < 0.0005) + .count(); + if tiny_n > 0 { + eprintln!( + "[cpu-census] {:>9.4} {:>5.1}% ({tiny_n} threads under 0.5 µs/frame each)", + per_frame(tiny), + tiny / process_ms * 100.0 + ); + } + eprintln!( + "[cpu-census] {:>9.4} {:>5.1}% (residual: threads exited in-window + sweep skew)", + per_frame(residual_ms), + residual_ms / process_ms * 100.0 + ); + // Name the churn: threads the per-second sweeps saw that are gone by the end snapshot. + // Their last cumulative reading minus their start reading (0 if born in-window) is a + // LOWER bound on what they contributed to the residual — they kept burning after the + // sweep that last saw them. + let mut churned: HashMap = HashMap::new(); + for (tid, (name, last_u, last_s)) in &census.seen { + if end_threads.contains_key(tid) { + continue; + } + let (start_u, start_s) = start.threads.get(tid).map_or((0, 0), |(_, u, s)| (*u, *s)); + let e = churned.entry(name.clone()).or_insert((0, 0.0)); + e.0 += 1; + e.1 += (last_u.saturating_sub(start_u) + last_s.saturating_sub(start_s)) as f64 / 1e6; + } + for (name, (n, ms)) in &churned { + eprintln!( + "[cpu-census] churn: {n} thread(s) '{}' died in-window, ≥{:.4} ms/frame of the residual", + if name.is_empty() { "(unnamed)" } else { name }, + per_frame(*ms) + ); + } + eprintln!( + "[cpu-census] sum check: Σ live {live_sum_ms:.1} + residual {residual_ms:.1} \ + = {:.1} vs process {process_ms:.1} ms (identity, by construction)", + live_sum_ms + residual_ms + ); + census.done = true; + } +} + /// `WOW_MESH_EVENTS=1`: per-second Mesh asset-event counts (see the plugin registration). The /// `sample` list names a few mutated asset ids so the writer can be found by grepping who holds /// that handle. diff --git a/crates/benilla-app/src/perf/hud.rs b/crates/benilla-app/src/perf/hud.rs index 5c51b248..3c2d48fa 100644 --- a/crates/benilla-app/src/perf/hud.rs +++ b/crates/benilla-app/src/perf/hud.rs @@ -1,29 +1,23 @@ -//! The standing dev HUD: a collapsed cost pill you can read while playing, and the full readout -//! behind a click. +//! The standing dev HUD: the cost pill, and nothing else. //! -//! **The pill is two small numbers and a bare latch arrow** (1448 pared it back). fps dim — the -//! familiar anchor, and by construction the number that cannot see cost (0717) — then process-CPU -//! cost per frame, the meter vsync cannot rail; both under-size, because the pill sits over the -//! game all session. The arrow is the spike latch: a burst is ~250 ms (0610) and the director is -//! looking at the game when it happens, so the evidence has to outlive the event — and its -//! appearance and colour are the *whole* signal (it once printed `▲261.9 main ×94`, a report -//! where an alarm belongs; the numbers wait behind the click). What left the pill entirely: the -//! minute-trend sparkline — a wiggle at 72 px; it is the expanded panel's full-width lane now, -//! beside the line that names its step. +//! **The pill is two small numbers** (1448 pared it back; 1454 made it the whole HUD; 1455 +//! dropped the spike arrow). fps dim — the familiar anchor, and by construction the number that +//! cannot see cost (0717) — then process-CPU cost per frame, the meter vsync cannot rail; both +//! under-size, because the pill sits over the game all session. Anything deeper is an +//! instrument's job, not a panel's: the journal (`WOW_FPS_JOURNAL`), the probes, Tracy, the +//! `frame hitch` log line and the stall self-sampler. The expanded egui readout that used to +//! live behind a click is gone (1454) — it duplicated the instruments at a standing cost — and +//! the spike-latch arrow went the same way (1455, the director's call). //! -//! **Drawn from a 4 Hz snapshot, not the live meters.** A label whose string changes every frame -//! re-shapes its galley every frame — cost that scales with every widget the surface carries, -//! booked into the very number the pill reports. Between snapshots every string is byte-identical, -//! so egui's galley cache absorbs the text; the meters keep sampling every frame — only the *view* -//! is quantized, and 250 ms is inside a human read of a number. (1448 *bounds* the price: the -//! drawing cost, before and after, sat below the ~0.4 ms noise floor of the interleaved legs — -//! 1370's "0.4–1.2 ms est" reads at its floor, and the diet is cheap insurance plus legibility, -//! not a measured megawin.) +//! **Drawn from a 4 Hz snapshot, not the live meters.** The pill renders from [`PerfHud::snap`]; +//! the meters keep sampling every frame — only the *view* is quantized, and 250 ms is inside a +//! human read of a number. //! -//! **Detail lives behind the click, and nowhere else.** The pill briefly carried a hover tooltip -//! holding the whole readout, on the theory that hovering costs no screen — but the pill is -//! top-center, the mouse crosses it constantly, and a panel-sized popup over the game is worse than -//! the panel it was avoiding. One surface, opened deliberately. +//! **The pill does not touch egui at all** (1453). Drawing anything through egui wakes the whole +//! lane — bevy_egui's per-frame pipeline plus a full-screen compositing camera — which the +//! director's live toggle priced at ~1 ms for a 20-glyph pill. So [`pill_quads`] lays the pill +//! onto the player-UI quad pass, whose append lane is rebuilt every frame anyway; since 1454 the +//! HUD has no egui surface left and [`crate::debug_panel`]'s 1445 gate no longer consults it. //! //! **The HUD does not own settings.** It briefly carried a VSync checkbox and an MSAA readout; //! VSync is a player video option now ([`crate::video`], the Graphics page's `gxVSync` row) and @@ -31,90 +25,40 @@ //! panel, and this one is `#[cfg(feature = "dev")]`, so anything a player must reach cannot live //! here at all. The measurement knob the checkbox actually existed for is `$WOW_NOVSYNC=1`. -use bevy::diagnostic::{DiagnosticsStore, EntityCountDiagnosticsPlugin}; +use benilla_ui::script::{JustifyH, JustifyV, Outline}; use bevy::prelude::*; use bevy::time::Real; -use bevy::window::{PresentMode, PrimaryWindow}; -use bevy_egui::{egui, EguiContexts}; +use bevy::window::{PrimaryWindow, Window}; -use super::stats::{FrameStats, Series}; -use super::FRAME_BUDGET_MS; -use crate::debug_panel::{overlay_text, OVERLAY_FILL, OVERLAY_TEXT, OVERLAY_TEXT_DIM}; +use super::stats::FrameStats; +use crate::ui_pass::{UiQuad, UiQuads}; +use crate::ui_text::{layout_text_quads, FontSpec, Justify, UiFontAtlas}; -const RED: egui::Color32 = egui::Color32::from_rgb(240, 120, 120); -const AMBER: egui::Color32 = egui::Color32::from_rgb(240, 190, 110); -const GREEN: egui::Color32 = egui::Color32::from_rgb(140, 220, 140); - -/// A latched spike is drawn amber until its peak is this many times its own baseline, then red. -const SPIKE_RED_RATIO: f32 = 3.0; - -/// The trend lane's height in the expanded panel (its width is the panel's). -const TREND_HEIGHT: f32 = 13.0; - -/// The pill's number size — under the 12 pt monospace default. The pill sits over the game all -/// session; the director asked for the numbers at a glance-size, not a reading-size (1448). -const PILL_NUM_SIZE: f32 = 10.0; +// ---- The quad pill (1453): the standing readout, drawn on the player-UI pass. -------------- +// The old egui overlay palette, restated as client-space sRGB floats for [`UiQuad::color`] +// (black alpha 224 fill; gray 235 text; gray 180 dim). +const Q_FILL: [f32; 4] = [0.0, 0.0, 0.0, 224.0 / 255.0]; +const Q_TEXT: [f32; 4] = [0.92, 0.92, 0.92, 1.0]; +/// `|cAARRGGBB` markup for the dim fps run (gray 180). +const Q_DIM_MARKUP: &str = "|cffb4b4b4"; +/// Paint order: the pill background one under the glyphs, both above every packed WoW z_key +/// (frame tuples never fill the top bits). +const Z_PILL_BG: u64 = u64::MAX - 1; +const Z_PILL: u64 = u64::MAX; +/// The quad pill's font height (logical px) and box padding. +const PILL_QUAD_PX: f32 = 12.0; +const PILL_PAD: Vec2 = Vec2::new(9.0, 4.0); +/// Top-center offset. +const PILL_TOP: f32 = 8.0; /// How often the drawn snapshot advances. Fast enough that the numbers read as live and a latched -/// badge appears within a perceptual beat; slow enough that between refreshes every galley is -/// byte-identical and egui's shape cache absorbs the whole text layout (see the module doc). +/// badge appears within a perceptual beat; slow enough that between refreshes the pill's cached +/// quads are reused byte-identical (see [`pill_quads`]). const HUD_REFRESH_SECS: f32 = 0.25; -/// **The ruler.** The expanded panel is as wide as this string renders in the monospace face — -/// or as wide as the pill above it, whichever is more — and every line inside either fits that or -/// wraps into it. No line is allowed to decide the width by being long. -/// -/// It is a *measured* string rather than a pixel constant so the panel stays correct at any font -/// size or UI scale — and it is written at full precision (`000.0`, not `20.2`) so the widest -/// value a field can ever hold still fits. Three tests hold the invariant from both sides: the -/// panel never exceeds its bound, always reaches it, and the ruler (not the pill) is what governs -/// whenever no spike badge is up. -/// -/// **Why a governed width at all, twice over.** First, the numbers change width as they change -/// value (`8.55` → `11.73`), so an auto-sized panel jitters under your eye while you read it. -/// Second — and this is what actually shipped broken — auto-sizing here does not merely wobble, it -/// blows up: -/// -/// - [`crate::debug_panel::overlay_text`] sets `TextWrapMode::Extend`, so **every label allocates -/// its full natural width and ignores `max_rect` entirely.** One long line therefore *defines* -/// the window width, and `set_width` alone cannot stop it. (The line that shipped broken was -/// `SpikeKind::describe`, ~110 characters; 1448 moved it to hover, but the `Wrap` below stays — -/// it is the fence that stops the *next* long label, not a patch for that one.) -/// - `Area` runs its sizing pass only on the frame the area is *created* -/// (`sizing_pass = state.is_none()`, egui 0.33 `containers/area.rs`). This HUD is born collapsed, -/// so that pass measures the pill; every later expand has no sizing pass, and `Separator` falls -/// through to `available_size_before_wrap()` — the room it *could* take. -/// -/// Together those are the ragged panel the director reported: prose setting the width, separators -/// and the graph stretching to whatever that came out as, and the short numeric lines not. The fix -/// is both halves — a ruler, and `TextWrapMode::Wrap` inside the panel so prose wraps instead of -/// measuring. -const PANEL_RULER: &str = "trend 000.0 → 000.0 ms (+000.0/min)"; - -/// The panel's content width: [`PANEL_RULER`], measured in the live monospace face. -/// -/// Measured as *glyph advance × character count* rather than by laying the string out: that is -/// what a monospace column actually is, and it costs one cached glyph lookup instead of a full -/// text layout on a path that runs every frame the panel is open. -fn panel_width(ui: &egui::Ui) -> f32 { - let font = egui::TextStyle::Monospace.resolve(ui.style()); - let advance = ui.ctx().fonts_mut(|f| f.glyph_width(&font, '0')); - advance * PANEL_RULER.chars().count() as f32 -} - -/// Does this present mode sync to the display? Synced, the HUD's wall-clock numbers measure the -/// present grant, not our cost — the stats lines switch meaning on it. -pub(super) fn synced_mode(mode: PresentMode) -> bool { - !matches!( - mode, - PresentMode::AutoNoVsync | PresentMode::Immediate | PresentMode::Mailbox - ) -} - -/// HUD state. The **dev chord + `P`** toggles `visible` (default on — it's a standing dev surface); -/// `expanded` is the click-to-open full readout (default off — the cost pill until clicked). -/// `visible` is `pub(crate)` so the capture harness ([`crate::capture`]) can force the overlay off -/// for pristine, UI-free screenshots. +/// HUD state. The **dev chord + `P`** toggles `visible` (default on — it's a standing dev +/// surface). `visible` is `pub(crate)` so the capture harness ([`crate::capture`]) can force the +/// overlay off for pristine, UI-free screenshots. /// /// **`WOW_PERF_HUD=0` starts it hidden**, which is how the HUD gets priced. 1370 records the open /// gap: every campaign anchor is measured on a binary that is drawing this overlay, at a cost @@ -126,15 +70,12 @@ pub(super) fn synced_mode(mode: PresentMode) -> bool { #[derive(Resource)] pub(crate) struct PerfHud { pub(crate) visible: bool, - /// Full stats shown? Toggled by clicking the pill; the cost pill alone when `false`. - expanded: bool, - /// The snapshot the HUD draws from — a copy of the meters taken every [`HUD_REFRESH_SECS`], + /// The snapshot the pill draws from — a copy of the meters taken every [`HUD_REFRESH_SECS`], /// so the strings it formats hold still between refreshes (the module doc's cost argument). /// The live [`FrameStats`] keeps sampling every frame; this is only the view. snap: FrameStats, - /// The clock `snap` was taken at. Spike ages and hold windows are computed against this, not - /// the live clock, so they hold still with the rest of the view — and it doubles as the - /// refresh timer. + /// The clock `snap` was taken at. Spike ages are computed against this, not the live clock, + /// so they hold still with the rest of the view — and it doubles as the refresh timer. snap_at: f32, } @@ -142,7 +83,6 @@ impl Default for PerfHud { fn default() -> Self { Self { visible: std::env::var("WOW_PERF_HUD").as_deref() != Ok("0"), - expanded: false, snap: FrameStats::default(), // −∞, so the very first frame refreshes rather than drawing an empty snapshot. snap_at: f32::NEG_INFINITY, @@ -169,503 +109,119 @@ pub(super) fn toggle_hud(keys: Res>, mut hud: ResMut, stats: Res, time: Res>, - diagnostics: Res, - windows: Query<&Window, With>, -) -> Result { - if !hud.visible { - return Ok(()); - } - let ctx = contexts.ctx_mut()?; - let synced = windows - .single() - .map(|w| synced_mode(w.present_mode)) - .unwrap_or(true); - hud.maybe_refresh(&stats, time.elapsed_secs()); - - // A title-less, anchored window — minimal chrome (no title bar, no resize) but the stable - // auto-sizing of a `Window`, so expanding to the full readout doesn't flash a mislaid first - // frame the way a raw `Area` does. - let hud = &mut *hud; - let mut clicked = false; - egui::Window::new("perf_hud") - .title_bar(false) - .resizable(false) - .collapsible(false) - .movable(false) - .anchor(egui::Align2::CENTER_TOP, egui::vec2(0.0, 8.0)) - .frame( - egui::Frame::NONE - .inner_margin(egui::Margin::symmetric(8, 5)) - .corner_radius(5.0) - .fill(OVERLAY_FILL), - ) - .show(ctx, |ui| { - clicked = draw_hud( - ui, - &hud.snap, - &diagnostics, - synced, - hud.snap_at, - hud.expanded, - ); - }); - if clicked { - hud.expanded = !hud.expanded; - } - Ok(()) -} - -/// Lay the whole HUD out into `ui`; returns whether the toggle strip was clicked. -/// -/// Split out of [`perf_hud_ui`] so the layout can be driven headless by a real `egui::Context` in -/// a test — the width invariant this panel kept breaking is a *layout* property, and the only -/// honest way to hold it is to lay it out and measure (see `panel_layout_is_governed_by_the_ruler`). -pub(super) fn draw_hud( - ui: &mut egui::Ui, - stats: &FrameStats, - diagnostics: &DiagnosticsStore, - synced: bool, - now: f32, - expanded: bool, -) -> bool { - overlay_text(ui); - let pill = collapsed_pill(ui, stats, now); - if expanded { - // The wider of the ruler and the pill above it. The pill is drawn first and `set_width` - // can only grow an already-allocated `min_rect`, never shrink it — so a pill carrying a - // spike badge is genuinely wider than the ruler, and pretending otherwise would just move - // the raggedness rather than fix it. A panel narrower than its own header is not a panel. - ui.set_width(panel_width(ui).max(pill.width())); - // The other half, and the one `set_width` alone could not do: `overlay_text` leaves labels - // on `TextWrapMode::Extend`, where they allocate their natural width and ignore `max_rect` - // entirely — so prose *measures* the window instead of fitting it (see [`PANEL_RULER`]). - ui.style_mut().wrap_mode = Some(egui::TextWrapMode::Wrap); - ui.separator(); - expanded_readout(ui, stats, diagnostics, synced, now); - } - // The click target is the whole top strip, not the row of glyphs: `min_rect` is now the - // laid-out content, so when the readout below is wider than the numbers above, the space - // beside them is still the toggle rather than dead pixels. Registered last, so it sits above - // the labels it spans. - let mut strip = pill; - strip.max.x = strip.max.x.max(ui.min_rect().max.x); - ui.interact(strip, ui.id().with("pill"), egui::Sense::click()) - .clicked() -} - -/// The collapsed pill: fps (dim), the cost headline — both small — and the bare latch arrow. -/// Returns the row's rect; the caller makes the strip that spans it the toggle. -/// -/// The arrow carries no numbers: the badge once printed `▲261.9 main ×94` over the game, which -/// is a report, not an alarm (director, 1448). Its appearance and its colour are the whole -/// signal; the numbers wait behind the click. -/// -/// **No hover tooltip.** It used to carry the detail so the expanded panel would be unnecessary -/// while playing — but the pill sits top-center, the mouse passes through constantly, and the -/// result was a panel-sized popup covering the game unbidden. Detail lives behind the click now, -/// where it is asked for. -fn collapsed_pill(ui: &mut egui::Ui, stats: &FrameStats, now: f32) -> egui::Rect { - let spike = stats.spike(now); - ui.horizontal(|ui| { - ui.spacing_mut().item_spacing.x = 8.0; - - // fps, dimmed: the familiar anchor, and by construction the number that cannot see - // any of this (0717). - ui.label( - egui::RichText::new(format!("{:.0} fps", stats.fps())) - .color(OVERLAY_TEXT_DIM) - .monospace() - .size(PILL_NUM_SIZE), - ); - - // The headline: process CPU per frame, the meter vsync cannot rail (0717). - match stats.cpu.mean() { - Some(cpu) => ui.label( - egui::RichText::new(format!("{cpu:.1} ms")) - .color(OVERLAY_TEXT) - .monospace() - .strong() - .size(PILL_NUM_SIZE), - ), - None => ui.label( - egui::RichText::new("-- ms") - .color(OVERLAY_TEXT_DIM) - .monospace() - .size(PILL_NUM_SIZE), - ), - }; - - // The latch. Present only when something actually happened, so its mere appearance is - // the signal — no scanning a number for a change. - if let Some(s) = spike { - let col = if s.peak_ms >= s.baseline_ms * SPIKE_RED_RATIO { - RED - } else { - AMBER - }; - ui.label(egui::RichText::new("▲").color(col).strong()); - } - }) - .response - .rect -} - -/// The minute-long trend of per-second median CPU cost, at the expanded panel's full width (1448 -/// moved it off the pill, where 72 px showed a wiggle, not a shape). Flat means nothing changed; a -/// step means the scene got more (or less) expensive and stayed there — the only lane that can see -/// that, since a sustained cost is its own baseline in every other one. -fn trend_sparkline(ui: &mut egui::Ui, trend: &Series, hi: f32) { - let (rect, _) = ui.allocate_exact_size( - egui::vec2(ui.available_width(), TREND_HEIGHT), - egui::Sense::hover(), - ); - if trend.len() < 2 { - return; - } - let painter = ui.painter_at(rect); - // Scaled to the window's p90, **not its max** — and the current value always fits, so nothing - // that matters right now is ever off the top. One launch sample (a loading frame is ~110 ms - // against a settled 8.5) is enough to press an entire minute of real signal into the bottom 7% - // of the box, which is what the lane looked like on the director's screen: a flat line. The - // clamp in `to_y` lets a true outlier clip instead of flattening its neighbours. - let hi = (hi.max(trend.last())).max(0.001) * 1.15; - let to_y = |ms: f32| rect.bottom() - (ms / hi).clamp(0.0, 1.0) * rect.height(); - - // Where the window started, so a step reads as a departure from something rather than as an - // anonymous wiggle. - let start = trend.iter().next().unwrap_or(0.0); - painter.hline( - rect.x_range(), - to_y(start), - egui::Stroke::new(1.0_f32, egui::Color32::from_gray(90)), - ); - - let dx = rect.width() / (trend.cap().max(2) - 1) as f32; - let points: Vec = trend - .iter() - .enumerate() - .map(|(i, ms)| egui::pos2(rect.left() + i as f32 * dx, to_y(ms))) - .collect(); - let col = if trend.last() > start * 1.15 { - AMBER - } else { - GREEN - }; - painter.add(egui::Shape::line(points, egui::Stroke::new(1.0_f32, col))); -} - -/// The full readout, in two answers: **is it running well** (the interval we're being granted and -/// how often we missed it), then **where the time goes** (the percentile table, the trend, the -/// graph, and the latched spike in full). -/// -/// It used to be nine lines answering those two questions three times over — a `last` sample the -/// graph below already drew, the p50s of `cpu` and `main` restated underneath as means, and a pair -/// of controls — with a *second* copy of most of it in a hover tooltip that opened whenever the -/// mouse crossed the pill. Everything appears once, here, behind the click. -fn expanded_readout( - ui: &mut egui::Ui, - stats: &FrameStats, - diagnostics: &DiagnosticsStore, - synced: bool, - now: f32, ) { - let rail = stats.rail_ms(); - // Synced, a small over is rail jitter, not cost — red only past the missed-interval threshold - // there. Uncapped, wall time is our cost and the 60 fps floor is the honest bar. - let red_above = if synced { - stats.dropped_above_ms() - } else { - FRAME_BUDGET_MS - }; - - // Both header lines are monospace and short enough to sit inside [`PANEL_RULER`]; the prose - // they used to carry ("observed", "60 fps floor") moved to the hover, which is free. - if synced { - ui.label( - egui::RichText::new(format!( - "interval {rail:>6.2} ms ({:.0} Hz)", - if rail > 0.0 { 1000.0 / rail } else { 0.0 } - )) - .color(OVERLAY_TEXT_DIM) - .monospace(), - ) - .on_hover_text( - "the present interval as OBSERVED, not assumed — an adaptive panel has no fixed \ - rail (0294), so the only honest answer is what the display has been granting", - ); - } else { - ui.label( - egui::RichText::new(format!("uncapped {FRAME_BUDGET_MS:>6.2} ms budget")) - .color(OVERLAY_TEXT_DIM) - .monospace(), - ) - .on_hover_text("uncapped: wall time is our real frame cost, against the 60 fps floor"); - } - - let (over_n, over_frac) = stats.wall.frames_over(red_above); - let ob_col = if over_frac > 0.0 { - RED - } else { - OVERLAY_TEXT_DIM - }; - // Synced: "missed" = missed present intervals — the felt metric; wall time can't say more - // while it rails at the grant. Uncapped: the honest over-budget count against the 16.7 floor. - ui.label( - egui::RichText::new(format!( - "{:<8} {over_n}/{} ({:.0}%)", - if synced { "missed" } else { "over" }, - stats.wall.len(), - over_frac * 100.0 - )) - .color(ob_col) - .monospace(), - ) - .on_hover_text(if synced { - "frames past 1.5x the OBSERVED present interval — a missed display interval. \ - The interval is measured, not assumed at 60 Hz, so this counts a 120 -> 60 drop \ - (which a fixed 25 ms threshold cannot see)" - } else { - "frames past the 16.7 ms budget (uncapped: wall time ~= real frame cost)" - }); - - ui.add_space(4.0); - // One header instead of the labels repeated on every row — the columns are the same three - // every time, so naming them once is both shorter and easier to read down. - ui.label( - egui::RichText::new(format!("{:<5}{:>8}{:>8}{:>8}", "ms", "p50", "p99", "max")) - .color(OVERLAY_TEXT_DIM) - .monospace(), - ); - for (name, series, why) in [ - ( - "cpu", - &stats.cpu, - "process CPU per frame, summed across every thread — our work, not the display's \ - present grant; comparable with the probes' cpu_ms and a reporter's CPU %", - ), - ( - "main", - &stats.main, - "CPU consumed by the main thread alone (CLOCK_THREAD_CPUTIME_ID) — the serialized \ - half of the line above. A worker-pool burst inflates `cpu` without touching this \ - one, and only this one is what a stutter is made of", - ), - ( - "wall", - &stats.wall, - "the frame interval itself. While synced this measures the display's grant, not our \ - cost (0717) — read it for missed intervals, not for how expensive we are", - ), - ] { - let (p50, p99, max) = series.percentiles(); - ui.label( - egui::RichText::new(format!("{name:<5}{p50:>8.2}{p99:>8.2}{max:>8.2}")).monospace(), - ) - .on_hover_text(why); - } - - // The creep lane: the sparkline shows the shape, the line under it names the step. - if let Some((first, last)) = stats.trend_ends() { - ui.add_space(2.0); - trend_sparkline(ui, &stats.trend, stats.trend_hi()); - let delta = last - first; - ui.label( - egui::RichText::new(format!("trend {first:.1} → {last:.1} ms ({delta:+.1}/min)")) - // `.monospace()` is load-bearing, not styling: the proportional face has no glyph for - // U+2192 and drew a tofu box on the director's screen. The mono face has it. - .monospace() - .color(if delta > first * 0.15 { - AMBER - } else { - OVERLAY_TEXT_DIM - }), - ); - } - - frame_graph(ui, stats, red_above); - - let entities = diagnostics - .get(&EntityCountDiagnosticsPlugin::ENTITY_COUNT) - .and_then(|d| d.value()) - .unwrap_or(0.0); - ui.label( - egui::RichText::new(format!("{:<8} {entities:.0}", "entities")) - .color(OVERLAY_TEXT_DIM) - .monospace(), - ); - - // The latch in full — only when one is latched; a quiet panel says nothing about it (1448 - // dropped the "no spike" placeholder and the inline prose). The pill's arrow carries no - // numbers, so this line is where the spike is actually read: kind, peak against baseline, - // age. The frame count, the *meaning* of the kind, and the burst count wait on hover — the - // panel stays numbers; the ~110-character `describe()` used to be the widest and least-read - // thing on it. - if let Some(s) = stats.spike(now) { - let mut why = format!("{} frames — {}", s.frames, s.kind.describe()); - let bursts = stats.recent_bursts(now); - if bursts > 1 { - why = format!("{why} — {bursts} bursts in the last 10 s; the worst is shown"); - } - ui.label( - egui::RichText::new(format!( - "spike {} {:.1} over {:.1}, {:.0}s ago", - s.kind.tag(), - s.peak_ms, - s.baseline_ms, - (now - s.at).max(0.0) - )) - .color(AMBER) - .monospace(), - ) - .on_hover_text(why); + if hud.visible { + let now = time.elapsed_secs(); + hud.maybe_refresh(&stats, now); } } -/// The frame-time graph: the windowed wall samples as a polyline with the missed-interval line in -/// red. Scaled to at least twice the observed interval so a dropped (doubled) frame reads clearly. -fn frame_graph(ui: &mut egui::Ui, stats: &FrameStats, red_above: f32) { - let (rect, _) = - ui.allocate_exact_size(egui::vec2(ui.available_width(), 52.0), egui::Sense::hover()); - if stats.wall.is_empty() { +/// The pill as ~20 quads on the player-UI pass (decision 1453). The append lane is rebuilt every +/// frame anyway, so the marginal cost is the clone of a cached Vec — where the old egui pill woke +/// bevy_egui's whole pipeline plus a full-screen compositing camera (~1 ms on the director's live +/// toggle). Glyphs are laid out only when the snapshot ticks or the window resizes. +pub(super) fn pill_quads( + hud: Res, + atlas: Option>, + windows: Query<&Window, With>, + mut quads: ResMut, + mut cache: Local>, +) { + if !hud.visible { return; } - let painter = ui.painter_at(rect); - let floor = (stats.rail_ms() * 2.0).max(33.0); - let max_ms = stats.wall.iter().fold(floor, f32::max); - let to_y = |ms: f32| rect.bottom() - (ms / max_ms).clamp(0.0, 1.0) * rect.height(); + let (Some(atlas), Ok(win)) = (atlas, windows.single()) else { + return; // headless: nothing draws, nothing to price + }; + let win_w = win.width(); + let stale = !matches!(&*cache, Some(c) if c.snap_at == hud.snap_at && c.win_w == win_w); + if stale { + let cpu = hud.snap.cpu.mean(); + let fps = hud.snap.fps(); + // One string, the dim run via markup: "59 fps 8.5 ms" — fps dim, cost in full text. + let text = match cpu { + Some(cpu) => format!("{Q_DIM_MARKUP}{fps:.0} fps|r {cpu:.1} ms"), + None => format!("{Q_DIM_MARKUP}-- ms"), + }; + let center = Vec2::new(win_w * 0.5, 0.0); // measured first, then shifted under PILL_TOP + let mut e = atlas.lock(); + let glyphs = layout_text_quads( + &mut e, + &text, + Rect::from_center_size(center, Vec2::ZERO), + Q_TEXT, + Justify { + h: JustifyH::Center, + v: JustifyV::Middle, + }, + Z_PILL, + FontSpec { + path: None, + height: Some(PILL_QUAD_PX), + outline: Outline::None, + alpha_gradient: None, + }, + ); + drop(e); + let bounds = glyphs + .iter() + .map(|q| q.rect) + .reduce(|a, b| a.union(b)) + .unwrap_or(Rect::from_center_size(center, Vec2::ZERO)); + let strip = Rect::new( + bounds.min.x - PILL_PAD.x, + bounds.min.y - PILL_PAD.y, + bounds.max.x + PILL_PAD.x, + bounds.max.y + PILL_PAD.y, + ); + // Measured about y=0; seat the whole strip at PILL_TOP. + let dy = PILL_TOP - strip.min.y; + let shift = |r: Rect| Rect::new(r.min.x, r.min.y + dy, r.max.x, r.max.y + dy); + let strip = shift(strip); + let mut out = vec![UiQuad { + rect: strip, + z_key: Z_PILL_BG, + color: Q_FILL, + ..Default::default() + }]; + for mut q in glyphs { + q.rect = shift(q.rect); + out.push(q); + } + *cache = Some(PillCache { + snap_at: hud.snap_at, + win_w, + quads: out, + }); + } + let Some(c) = &*cache else { return }; + quads.overlays.extend(c.quads.iter().cloned()); +} - painter.hline( - rect.x_range(), - to_y(red_above), - egui::Stroke::new(1.0_f32, egui::Color32::from_rgb(200, 80, 80)), - ); - - let dx = rect.width() / stats.wall.cap() as f32; - let points: Vec = stats - .wall - .iter() - .enumerate() - .map(|(i, ms)| egui::pos2(rect.left() + i as f32 * dx, to_y(ms))) - .collect(); - painter.add(egui::Shape::line(points, egui::Stroke::new(1.0_f32, GREEN))); +/// [`pill_quads`]' cache: the laid-out pill, valid for one snapshot tick at one window width. +pub(super) struct PillCache { + snap_at: f32, + win_w: f32, + quads: Vec, } #[cfg(test)] mod tests { use super::*; - /// The panel, laid out by a real `egui::Context`, headless. - /// - /// **It must run more than one pass, and that is the whole point.** `Area` runs its sizing - /// pass only on the frame it is created; the width bug lived exclusively on every *later* - /// frame, where `Separator` and unwrapped labels reach for room the content never asked for. - /// A one-pass test would have passed against the broken build. - /// - /// Returns `(content width, ruler width)` after the final pass. - fn lay_out(stats: &FrameStats, now: f32, expanded: bool, passes: usize) -> (f32, f32) { - let ctx = egui::Context::default(); - let diagnostics = DiagnosticsStore::default(); - let (mut width, mut ruler) = (0.0, 0.0); - for _ in 0..passes { - let _ = ctx.run(egui::RawInput::default(), |ctx| { - egui::Window::new("perf_hud") - .title_bar(false) - .resizable(false) - .collapsible(false) - .movable(false) - .show(ctx, |ui| { - draw_hud(ui, stats, &diagnostics, true, now, expanded); - width = ui.min_rect().width(); - ruler = panel_width(ui); - }); - }); - } - (width, ruler) - } - - /// A settled window plus a latched `Stalled` spike — whose `describe()` is ~110 characters, - /// the longest string the panel can ever draw, and precisely what used to measure the window. - fn stats_with_a_latched_spike() -> (FrameStats, f32) { - let mut stats = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (16.6, 20.0, 5.0)).collect(); - let mut t = stats.feed_frames(&calm, 0.0, 1.0 / 60.0); - t = stats.feed_frames(&[(40.0, 20.0, 5.0)], t, 1.0 / 60.0); - t = stats.feed_frames(&[(16.6, 20.0, 5.0)], t, 1.0 / 60.0); - assert!( - stats.spike(t).is_some(), - "the fixture must actually latch — otherwise this measures the easy case" - ); - (stats, t) - } - - /// **The invariant the panel kept breaking:** the expanded panel is exactly as wide as the - /// wider of [`PANEL_RULER`] and the pill above it — never wider. Prose wraps, numbers fit, and - /// no single long line gets to decide the width by being long. - /// - /// Three shipped builds widened this panel, the worst to ~5x the ruler, and each was reported - /// by the director rather than caught here. All three fail this test. - #[test] - fn panel_layout_is_governed_by_the_ruler() { - let (stats, t) = stats_with_a_latched_spike(); - let (pill, _) = lay_out(&stats, t, false, 3); - let (width, ruler) = lay_out(&stats, t, true, 3); - let governing = ruler.max(pill); - assert!( - width <= governing + 1.0, - "the expanded panel is {width:.1} px against a {governing:.1} px bound \ - (ruler {ruler:.1}, pill {pill:.1}) — something in it is refusing to wrap \ - (TextWrapMode::Extend) or reaching for available_width" - ); - } - - /// And it must be genuinely governed, not accidentally narrow: the panel should actually - /// reach its bound, or the guard above is vacuous. - #[test] - fn the_expanded_panel_fills_its_bound() { - let (stats, t) = stats_with_a_latched_spike(); - let (pill, _) = lay_out(&stats, t, false, 3); - let (width, ruler) = lay_out(&stats, t, true, 3); - let governing = ruler.max(pill); - assert!( - width >= governing - 1.0, - "the expanded panel is only {width:.1} px of a {governing:.1} px bound" - ); - } - - /// With no spike latched the pill is comfortably inside the ruler, so the ruler is what - /// governs in the ordinary case — the pill only takes over while a badge is up. - #[test] - fn the_ruler_governs_when_no_spike_is_latched() { - let mut stats = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (16.6, 20.0, 5.0)).collect(); - let t = stats.feed_frames(&calm, 0.0, 1.0 / 60.0); - assert!(stats.spike(t).is_none(), "the fixture must be quiet"); - - let (pill, ruler) = lay_out(&stats, t, false, 3); - assert!( - pill < ruler, - "the quiet pill is {pill:.1} px against a {ruler:.1} px ruler — the ruler should \ - govern the ordinary panel, or its width tracks the badge and jitters" - ); - let (width, _) = lay_out(&stats, t, true, 3); - assert!( - (width - ruler).abs() <= 1.0, - "the quiet panel is {width:.1} px, not the {ruler:.1} px ruler" - ); - } - /// The view the HUD draws only advances on the refresh interval — between ticks it holds - /// still, which is the entire cost argument (identical strings are what the galley cache can - /// absorb) — and a refresh adopts the live meters wholesale. + /// still, which is the entire cost argument (identical snapshots are what the quad cache can + /// reuse) — and a refresh adopts the live meters wholesale. #[test] fn the_snapshot_advances_on_the_interval_not_per_frame() { let mut live = FrameStats::default(); - let frames: Vec<_> = (0..60).map(|_| (16.6, 20.0, 5.0)).collect(); + let frames: Vec<_> = (0..60).map(|_| (16.6, 20.0)).collect(); let t = live.feed_frames(&frames, 0.0, 1.0 / 60.0); let mut hud = PerfHud::default(); @@ -677,7 +233,7 @@ mod tests { ); assert_eq!(hud.snap_at, t); - let t2 = live.feed_frames(&[(40.0, 20.0, 5.0)], t, 1.0 / 60.0); + let t2 = live.feed_frames(&[(40.0, 20.0)], t, 1.0 / 60.0); hud.maybe_refresh(&live, t2); assert_eq!( hud.snap.wall.len(), diff --git a/crates/benilla-app/src/perf/mod.rs b/crates/benilla-app/src/perf/mod.rs index 660f545f..7eb285ba 100644 --- a/crates/benilla-app/src/perf/mod.rs +++ b/crates/benilla-app/src/perf/mod.rs @@ -1,14 +1,14 @@ //! `perf` — performance instrumentation + the standing dev HUD ([`PerfPlugin`]). //! //! Owns the **frame-cost measurement layer** that every future subsystem is measured against (the -//! standard), and draws the always-on pill (top-center) that you **click to expand** into the full -//! readout; the **dev chord + `P`** toggles the whole HUD (`Ctrl+Shift+P` — decisions -//! 0585/0867/0870). +//! standard), and draws the always-on cost pill (top-center) — the whole HUD since 1454; anything +//! deeper is an instrument's job (the journal, the probes, Tracy). The **dev chord + `P`** toggles +//! it (`Ctrl+Shift+P` — decisions 0585/0867/0870). //! //! The concerns, one file each: //! - [`clock`] — the three CPU clocks (process, main thread, machine) every number is denominated in, -//! - [`stats`] — the rolling windows, their tails, and the spike latch, -//! - [`hud`] — the collapsed cost pill and the expanded readout, +//! - [`stats`] — the rolling windows the pill reads, +//! - [`hud`] — the standing cost pill, //! - [`trace`] / [`journal`] — the two CSV instruments (`WOW_STREAM_TRACE`, `WOW_FPS_JOURNAL`), //! - [`stall`] — the stuck-main-thread self-sampler (macOS), //! - [`census`] — the env-gated premise counters. @@ -36,8 +36,8 @@ //! 0.015/0.019/0.049 ms across 256²/1920×1080/4096² clears, 12/12 reproducible. It needs two //! sentinel render-graph nodes at ~0.03 ms/frame, and the query set must be resolved in a //! *different* command buffer than the timed pass or Metal returns zeros. Until that is built, a -//! GPU-bound frame is identified rather than timed: it is the one that runs long while both CPU -//! meters stay flat ([`stats::SpikeKind::Stalled`]). +//! GPU-bound frame is identified rather than timed: it is the one that runs long while the CPU +//! meters stay flat (read them side by side in the journal or a probe line). mod census; mod clock; @@ -49,7 +49,6 @@ mod stall; mod stats; mod trace; -use bevy::diagnostic::{EntityCountDiagnosticsPlugin, FrameTimeDiagnosticsPlugin}; use bevy::prelude::*; use bevy::render::diagnostic::RenderDiagnosticsPlugin; @@ -65,32 +64,34 @@ pub struct PerfPlugin; impl Plugin for PerfPlugin { fn build(&self, app: &mut App) { - app.add_plugins(( - FrameTimeDiagnosticsPlugin::default(), - EntityCountDiagnosticsPlugin::default(), - // Render-pass timing (CPU-only on Apple Silicon — see the module header). Harmless if - // the backend can't record it; also the hook Tracy GPU uses on Vulkan/DX12. - RenderDiagnosticsPlugin, - )) - .init_resource::() - .init_resource::() - .insert_resource(trace::StreamTrace { - path: std::env::var("WOW_STREAM_TRACE").unwrap_or_default(), - frame: 0, - log_until: 0, - prev_cpu_secs: None, - prev_pipes_created: 0, - }) - .add_systems( - Update, - // `toggle_hud` needs no ordering against the UI keyboard feed any more: its dev - // chord can't be typed text, so there's no `UiKeyboardCapture` to read (decision 0585). - (hud::toggle_hud, stats::sample_frame_time), - ) - // `Last`, so a row carries everything this frame's Stream chain did — and the reset runs - // whether or not anything is tracing, or the counters would accumulate forever. - .add_systems(Last, trace::trace_stream) - .add_systems(bevy_egui::EguiPrimaryContextPass, hud::perf_hud_ui); + // Render-pass timing (CPU-only on Apple Silicon — see the module header). Harmless if + // the backend can't record it; also the hook Tracy GPU uses on Vulkan/DX12. + app.add_plugins(RenderDiagnosticsPlugin) + .init_resource::() + .init_resource::() + .insert_resource(trace::StreamTrace { + path: std::env::var("WOW_STREAM_TRACE").unwrap_or_default(), + frame: 0, + log_until: 0, + prev_cpu_secs: None, + prev_pipes_created: 0, + }) + .add_systems( + Update, + // `toggle_hud` needs no ordering against the UI keyboard feed any more: its dev + // chord can't be typed text, so there's no `UiKeyboardCapture` to read (decision 0585). + ( + hud::toggle_hud, + hud::refresh_hud_snapshot, + stats::sample_frame_time, + ), + ) + // The pill rides the player-UI quad pass (1453): appended with the other overlay + // producers, so the HUD costs a Vec clone and never touches the egui lane (1454). + .add_systems(Update, hud::pill_quads.in_set(crate::ui_pass::UiQuadAppend)) + // `Last`, so a row carries everything this frame's Stream chain did — and the reset runs + // whether or not anything is tracing, or the counters would accumulate forever. + .add_systems(Last, trace::trace_stream); // `WOW_MESH_EVENTS=1` — who churns Mesh assets per frame? The premise counter behind // the Stormwind trace's `allocate_and_free_meshes` row (0.86 ms/frame at a PARKED pin): // the allocator answers every Modified with a free+realloc, so a steady scene should @@ -126,6 +127,13 @@ impl Plugin for PerfPlugin { { app.add_systems(Update, census::row_bloat); } + // `WOW_CPU_CENSUS=:` — the per-thread CPU census (see its module doc): where + // the pill's cpu-ms goes, thread by thread, summing exactly to the process total. + #[cfg(target_os = "macos")] + if let Some(c) = census::cpu_census::CpuCensus::from_env() { + app.insert_resource(c); + app.add_systems(Update, census::cpu_census::cpu_census); + } #[cfg(target_os = "macos")] stall::plugin(app); // `WOW_GPU_MS=1` — the whole-frame GPU meter (its module doc owns the design and the diff --git a/crates/benilla-app/src/perf/stats.rs b/crates/benilla-app/src/perf/stats.rs index 4219421c..74b8d81f 100644 --- a/crates/benilla-app/src/perf/stats.rs +++ b/crates/benilla-app/src/perf/stats.rs @@ -1,89 +1,30 @@ -//! The frame-cost meters: one rolling window per series, their tails, and the spike latch. +//! The frame-cost meters the pill reads: a rolling window each of wall frame time and process +//! CPU per frame. //! -//! **Why the tail, and why per-series.** The HUD used to carry percentiles on wall frame time and a -//! flat *mean* on cost — so the client had a tail with no cost and a cost meter with no tail, and -//! `cpu p99` existed nowhere. That is exactly the shape a regression hides in: 0366 measured a run -//! whose per-second mean never passed 16.5 ms while nearly every second carried a few 19-29 ms -//! frames, and the tail was what the director read as "30 fps". 0610 adds the shape — a spike is a -//! burst of ~6 consecutive frames, ~250 ms of degraded time, not one bad frame. Six frames inside a -//! 300-sample mean move it by 2 %. +//! **The law (0717): while synced, wall frame time measures the display's present grant, not our +//! cost.** Only the CPU series measures work — it is the pill's headline. `wall` exists for the +//! dim fps anchor and the hitch log below, nothing else. //! -//! **Everything is measured against the window's own baseline, never against a constant.** 1355 -//! records the same slot drifting −3.3 cpu_ms between sessions on thermal state alone, and 1353 -//! records the pin-to-pin spread; an absolute threshold would be calibrated for one scene on one -//! afternoon. A spike here is "much more than *this* scene has been costing", which is what -//! noticing a regression actually means — and it works unchanged at 3 ms on an empty map and at -//! 16 ms in Stormwind. +//! This file used to carry a per-series spike latch (0610's burst detector) and the +//! median baselines it tested against; both left with their last surface — the pill's arrow +//! (1455, after 1454 removed the expanded panel). The standing stall record is the +//! `frame hitch` warn below plus the self-sampler ([`super::stall`]); burst-shaped analysis +//! belongs to the instruments (the journal, the probes, Tracy). use std::collections::VecDeque; -use bevy::ecs::system::NonSendMarker; use bevy::prelude::*; use bevy::time::Real; -use super::clock::{main_thread_cpu_secs, process_cpu_secs}; +use super::clock::process_cpu_secs; -/// Recent frames kept for the percentiles + the graph (~5 s at 60 fps, ~2.5 s at 120). +/// Recent frames kept for the pill's windowed means (~5 s at 60 fps, ~2.5 s at 120). pub(super) const SAMPLE_WINDOW: usize = 300; /// Frame duration above which a frame is logged as a hitch (a stall the player feels). Far above /// any present interval so it only fires on real stalls (load bursts), not normal jitter. const HITCH_LOG_MS: f32 = 250.0; -/// A frame past `DROPPED_FACTOR` × the **observed** present interval is a missed interval — the -/// metric a synced player actually feels (0717). -/// -/// The factor is 0717's, but the thing it multiplies is not. That record set the threshold at -/// 1.5 × a hardcoded 16.7 ms budget, which silently assumes a 60 Hz rail: on the director's -/// ProMotion panel granting ~120, a missed interval is 16.7 ms and lands *under* the 25 ms -/// threshold, so **every 120→60 drop went uncounted**. Multiplying the interval we can see instead -/// keeps 0717's semantics exactly at 60 Hz and restores them at any other refresh — including an -/// adaptive panel, which has no fixed rail at all (0294) and where the only honest answer to "what -/// is one interval" is "what the display has been giving us lately". -pub(super) const DROPPED_FACTOR: f32 = 1.5; - -/// A frame must exceed its series' baseline by this ratio to count as a spike. -const SPIKE_FACTOR: f32 = 1.5; - -/// ...**and** by at least this fraction of a present interval. Without the floor the ratio test -/// alone latches on noise: a main-thread baseline of 0.4 ms makes any 0.7 ms frame a "2× spike". -/// Half an interval is the point where an excess starts being able to cost a frame. -const SPIKE_FLOOR_OF_RAIL: f32 = 0.5; - -/// The floor's own floor, for the first second of a run and any pathological rail estimate. -const SPIKE_FLOOR_MIN_MS: f32 = 2.0; - -/// How long a finished burst stays on the pill after it ends. The whole point of the latch: a -/// spike lasts ~250 ms and the director is looking at the game, not at the HUD, so the evidence -/// has to outlive the event by long enough to glance at. -const LATCH_HOLD_SECS: f32 = 10.0; - -/// Consecutive frames a [`SpikeKind::Worker`] burst must last before the badge will show it. -/// -/// **Because `cpu` is a sum across threads, not a duration.** A frame in which six pool workers -/// happen to overlap carries six threads' milliseconds and trips the ratio test while costing the -/// frame nothing — the first live run of this HUD latched `▲31.3 work ×1` against `missed 0/300`, -/// which is the instrument reporting the scheduler rather than a regression. A real worker -/// regression is *sustained* (0610's burst is ~6 frames), so a few consecutive frames separates -/// the two cleanly. -/// -/// [`SpikeKind::Main`] and [`SpikeKind::Stalled`] are deliberately **not** gated: one long -/// main-thread frame is itself the stutter, and `Stalled` already had to exceed the -/// missed-interval threshold to classify at all. -const WORKER_BURST_FRAMES: u32 = 3; - -/// Baselines are re-derived this often, not every frame. A median moves slowly by construction, so -/// a one-second-stale baseline changes no verdict — and it keeps the collapsed pill's per-frame -/// path free of sorts (1370: the HUD is itself inside every campaign anchor). -const BASELINE_REFRESH_SECS: f32 = 1.0; - -/// Seconds of history the slow trend keeps — the timescale creep lives on. -/// -/// The fast window is ~2.5 s at 120 Hz: plenty to catch a burst, useless for noticing that a scene -/// which used to cost 15 ms now costs 19. One sample a second for a minute costs 60 floats and -/// makes a step change visible as a step. -pub(super) const TREND_WINDOW_SECS: usize = 60; - /// A rolling window of one cost series, in milliseconds, capped at its own length. #[derive(Clone)] pub(super) struct Series { @@ -106,161 +47,18 @@ impl Series { self.samples.push_back(ms); } - pub(super) fn cap(&self) -> usize { - self.cap - } - - pub(super) fn last(&self) -> f32 { - self.samples.back().copied().unwrap_or(0.0) - } - pub(super) fn len(&self) -> usize { self.samples.len() } - pub(super) fn is_empty(&self) -> bool { - self.samples.is_empty() - } - - pub(super) fn iter(&self) -> impl Iterator + '_ { - self.samples.iter().copied() - } - /// Windowed mean. `None` on an empty window, so a caller can tell "no data" from "zero cost". pub(super) fn mean(&self) -> Option { (!self.samples.is_empty()) .then(|| self.samples.iter().sum::() / self.samples.len() as f32) } - - /// `(p50, p99, max)` over the window. Sorts a copy — fine for a few-hundred-element dev HUD, - /// and deliberately **not** on the collapsed pill's per-frame path (see [`Baselines`]). - pub(super) fn percentiles(&self) -> (f32, f32, f32) { - if self.samples.is_empty() { - return (0.0, 0.0, 0.0); - } - let mut v: Vec = self.samples.iter().copied().collect(); - v.sort_by(f32::total_cmp); - let at = |q: f32| v[(((v.len() - 1) as f32) * q).round() as usize]; - (at(0.50), at(0.99), *v.last().unwrap()) - } - - /// The window's `q`-quantile. Sorts a copy, so like [`Self::percentiles`] it belongs off the - /// per-frame path — [`Baselines`] is where its caller reads the answer from. - fn quantile(&self, q: f32) -> f32 { - if self.samples.is_empty() { - return 0.0; - } - let mut v: Vec = self.samples.iter().copied().collect(); - v.sort_by(f32::total_cmp); - v[(((v.len() - 1) as f32) * q).round() as usize] - } - - /// The window's median alone — the baseline every spike test is relative to. - fn median(&self) -> f32 { - if self.samples.is_empty() { - return 0.0; - } - let mut v: Vec = self.samples.iter().copied().collect(); - v.sort_by(f32::total_cmp); - v[((v.len() - 1) / 2).min(v.len() - 1)] - } - - /// `(count, fraction)` of windowed frames above `threshold_ms`. - pub(super) fn frames_over(&self, threshold_ms: f32) -> (usize, f32) { - let n = self.samples.iter().filter(|&&ms| ms > threshold_ms).count(); - let frac = if self.samples.is_empty() { - 0.0 - } else { - n as f32 / self.samples.len() as f32 - }; - (n, frac) - } } -/// What a spike was blamed on. The three are distinguishable **without GPU timestamps**, which we -/// do not have in-client on Apple Silicon (see the module header of [`super`]): the question "were -/// we busy, or were we blocked?" is answered by whether the CPU meters moved with the frame. -#[derive(Clone, Copy, PartialEq, Eq, Debug)] -pub(super) enum SpikeKind { - /// Main-thread CPU ran long — our own systems, serialized, and the frame waited on them. The - /// most actionable kind: it is the one a player feels as a stutter. - Main, - /// Process CPU ran long while the main thread did not — a worker-pool burst (asset decode, - /// collider bake). Real work, but off the frame's critical path. - Worker, - /// The frame ran long while **neither** CPU meter moved: we were blocked, not busy. That is - /// the GPU or the present path. Stated as an inference, because it is one — a blocked - /// present-wait consumes no CPU (0717), so this is what its absence looks like from here. - Stalled, -} - -impl SpikeKind { - /// The short tag the expanded panel's spike line carries. - pub(super) fn tag(self) -> &'static str { - match self { - SpikeKind::Main => "main", - SpikeKind::Worker => "work", - SpikeKind::Stalled => "wait", - } - } - - pub(super) fn describe(self) -> &'static str { - match self { - SpikeKind::Main => { - "main-thread CPU ran long — our systems, on the frame's critical path" - } - SpikeKind::Worker => { - "process CPU ran long while the main thread did not — a worker-pool burst \ - (asset decode, collider bake), off the critical path" - } - SpikeKind::Stalled => { - "the frame ran long while neither CPU meter moved — blocked, not busy: \ - the GPU or the present path (inferred, we have no GPU timer on Apple Silicon)" - } - } - } -} - -/// A burst that has finished and must stay visible after it ended. -#[derive(Clone, Copy)] -pub(super) struct Spike { - /// Worst frame of the burst, in the tripping series' milliseconds. - pub(super) peak_ms: f32, - /// The series' baseline at the time, so the badge can say what "normal" was. - pub(super) baseline_ms: f32, - /// Consecutive frames the burst lasted. 0610: a spike is a burst, not a frame — the six-frame - /// version is what reads as a quarter-second of degraded time. - pub(super) frames: u32, - pub(super) kind: SpikeKind, - /// `Time` seconds at the burst's last frame. - pub(super) at: f32, -} - -/// Is this burst worth a badge? See [`WORKER_BURST_FRAMES`] — the one kind that needs to prove -/// itself is the one measured by a cross-thread sum. -fn reportable(s: &Spike) -> bool { - s.kind != SpikeKind::Worker || s.frames >= WORKER_BURST_FRAMES -} - -/// Medians re-derived once a second, off the per-frame path. -#[derive(Default, Clone)] -struct Baselines { - wall: f32, - cpu: f32, - main: f32, - /// The trend sparkline's y-scale: the trend window's p90, **not its max**. Derived here rather - /// than in the painter because it needs a sort and the painter runs every frame the panel is - /// open — and refreshed on exactly the tick that appends the sample it summarises, so it can - /// never lag by more than one point. - trend_hi: f32, - at: f32, -} - -/// The per-frame cost meters and everything derived from them. -/// -/// Three series, because they answer three different questions and 0717's law binds all of them: -/// while synced, **wall frame time is the display's grant, not our cost**. Only the CPU series -/// measure work. +/// The per-frame cost meters. /// /// `Clone` is for the HUD's 4 Hz snapshot (`PerfHud::maybe_refresh`) — a few hundred floats, /// four times a second. @@ -271,22 +69,7 @@ pub(super) struct FrameStats { /// Process CPU per frame, user+system across every thread (`getrusage`) — the campaign's /// currency (0736) and the meter the rail cannot fool (0717). pub(super) cpu: Series, - /// Main-thread CPU per frame. The serialized half of the above: what a hitch is made of. - pub(super) main: Series, - /// One `cpu` median per second, for [`TREND_WINDOW_SECS`]. The creep lane: the fast window - /// cannot see a regression that is merely *sustained*, because a sustained cost IS its own - /// baseline there. - pub(super) trend: Series, prev_cpu_secs: Option, - prev_main_secs: Option, - baselines: Baselines, - /// The burst currently accumulating, if this frame and its predecessors are tripping. - run: Option, - /// The worst burst inside the hold window — what the pill actually shows. - latched: Option, - /// Bursts that have finished inside the hold window, latched or not. - recent_bursts: u32, - recent_since: f32, } impl Default for FrameStats { @@ -294,37 +77,15 @@ impl Default for FrameStats { Self { wall: Series::new(SAMPLE_WINDOW), cpu: Series::new(SAMPLE_WINDOW), - main: Series::new(SAMPLE_WINDOW), - trend: Series::new(TREND_WINDOW_SECS), prev_cpu_secs: None, - prev_main_secs: None, - baselines: Baselines::default(), - run: None, - latched: None, - recent_bursts: 0, - recent_since: 0.0, } } } impl FrameStats { - /// The display's present interval as observed, not as assumed. See [`DROPPED_FACTOR`]. - pub(super) fn rail_ms(&self) -> f32 { - self.baselines.wall - } - - /// The threshold a frame must pass to count as a missed interval. - pub(super) fn dropped_above_ms(&self) -> f32 { - self.rail_ms() * DROPPED_FACTOR - } - - /// The sparkline's y-scale — see [`Baselines::trend_hi`]. - pub(super) fn trend_hi(&self) -> f32 { - self.baselines.trend_hi - } - /// Windowed mean frames per second. A mean, and labelled as one — it is the number that - /// cannot see a spike, which is why the pill draws it dim and small, never as the headline. + /// cannot see cost (0717), which is why the pill draws it dim and small, never as the + /// headline. pub(super) fn fps(&self) -> f32 { match self.wall.mean() { Some(mean) if mean > 0.0 => 1000.0 / mean, @@ -332,166 +93,23 @@ impl FrameStats { } } - /// The spike still inside its hold window, if any. - pub(super) fn spike(&self, now: f32) -> Option { - self.latched - .filter(|s| now - s.at < LATCH_HOLD_SECS) - .or(self.run) - .filter(reportable) - } - - /// Bursts finished inside the hold window — "it happened three times" is a different report - /// from "it happened once", and only the tooltip has room to say so. - pub(super) fn recent_bursts(&self, now: f32) -> u32 { - if now - self.recent_since < LATCH_HOLD_SECS { - self.recent_bursts - } else { - 0 - } - } - - /// How far a frame must sit above its baseline to count. Both tests must pass: the ratio, so - /// the rule travels between a 3 ms scene and a 16 ms one, and the floor, so it does not fire - /// inside the noise of a series whose baseline is a fraction of a millisecond. - fn spike_excess_ms(&self, baseline: f32) -> f32 { - let floor = (self.rail_ms() * SPIKE_FLOOR_OF_RAIL).max(SPIKE_FLOOR_MIN_MS); - floor.max(baseline * (SPIKE_FACTOR - 1.0)) - } - - /// Classify the frame just pushed. `None` on a normal frame. - /// - /// Order is deliberate and is the whole attribution: main-thread cost first (the actionable - /// kind), then a worker burst, and only if *neither* CPU meter moved is a long frame read as a - /// stall. A GPU-bound frame is precisely the one that is long while the CPU is flat. - fn classify(&self) -> Option<(SpikeKind, f32, f32)> { - let b = &self.baselines; - let tripped = |v: f32, base: f32| v - base > self.spike_excess_ms(base); - - if !self.main.is_empty() { - let v = self.main.last(); - if tripped(v, b.main) { - return Some((SpikeKind::Main, v, b.main)); - } - } - if !self.cpu.is_empty() { - let v = self.cpu.last(); - if tripped(v, b.cpu) { - return Some((SpikeKind::Worker, v, b.cpu)); - } - } - let v = self.wall.last(); - if v > self.dropped_above_ms() && tripped(v, b.wall) { - return Some((SpikeKind::Stalled, v, b.wall)); - } - None - } - - /// Extend or close the current burst. O(1) — this is the whole per-frame cost of the latch. - fn observe(&mut self, now: f32) { - match self.classify() { - Some((kind, peak, baseline)) => { - let run = self.run.get_or_insert(Spike { - peak_ms: peak, - baseline_ms: baseline, - frames: 0, - kind, - at: now, - }); - run.frames += 1; - run.at = now; - if peak > run.peak_ms { - run.peak_ms = peak; - // The worst frame of a burst names it: a burst that starts as a worker spill - // and peaks on the main thread is a main-thread event. - run.kind = kind; - run.baseline_ms = baseline; - } - } - None => { - // The burst (if any) just ended: commit it, unless it never earned a badge — a - // filtered burst is not a burst, or the tooltip would count three while the pill - // shows one. The latch keeps the WORST burst in the hold window rather than the - // most recent, so a small one cannot bury the big one you were meant to see. - if let Some(run) = self.run.take().filter(reportable) { - if now - self.recent_since >= LATCH_HOLD_SECS { - self.recent_bursts = 0; - self.recent_since = now; - } - self.recent_bursts += 1; - let expired = self - .latched - .is_none_or(|l| now - l.at >= LATCH_HOLD_SECS || run.peak_ms >= l.peak_ms); - if expired { - self.latched = Some(run); - } - } - } - } - } - - /// The trend's oldest and newest samples — "it used to cost this, it costs that now". `None` - /// until the window has enough history to make the comparison mean anything. - pub(super) fn trend_ends(&self) -> Option<(f32, f32)> { - (self.trend.len() >= 8).then(|| { - let mut it = self.trend.iter(); - let first = it.next().unwrap_or(0.0); - (first, self.trend.last()) - }) - } - - /// Drive the meters from a sibling module's test, on the same path [`sample_frame_time`] takes - /// minus the clocks. Each frame is `(wall_ms, cpu_ms, main_ms)`; returns the clock it left off - /// at. `hud`'s layout test needs a realistically-populated `FrameStats` — including a *latched - /// spike*, whose description is the longest string the panel can draw. + /// Drive the meters from a sibling module's test, on the same path [`sample_frame_time`] + /// takes minus the clocks. Each frame is `(wall_ms, cpu_ms)`; returns the clock it left off + /// at. `hud`'s snapshot test needs a realistically-populated `FrameStats`. #[cfg(test)] - pub(super) fn feed_frames(&mut self, frames: &[(f32, f32, f32)], start_t: f32, dt: f32) -> f32 { + pub(super) fn feed_frames(&mut self, frames: &[(f32, f32)], start_t: f32, dt: f32) -> f32 { let mut t = start_t; - for &(wall, cpu, main) in frames { + for &(wall, cpu) in frames { self.wall.push(wall); self.cpu.push(cpu); - self.main.push(main); - self.refresh_baselines(t); - if self.wall.len() > 1 && self.baselines.wall > 0.0 { - self.observe(t); - } t += dt; } t } - - fn refresh_baselines(&mut self, now: f32) { - if now - self.baselines.at < BASELINE_REFRESH_SECS && self.baselines.at > 0.0 { - return; - } - self.baselines = Baselines { - wall: self.wall.median(), - cpu: self.cpu.median(), - main: self.main.median(), - trend_hi: self.baselines.trend_hi, - at: now, - }; - // The trend samples the same median the baseline does, so the two lanes cannot disagree - // about what "normal right now" is — the badge and the sparkline read one truth. - if !self.cpu.is_empty() { - self.trend.push(self.baselines.cpu); - self.baselines.trend_hi = self.trend.quantile(0.90); - } - } } -/// Sample every meter for this frame. -/// -/// **`NonSendMarker` is load-bearing, not decoration.** Bevy's executor runs systems across the -/// task pool, and [`main_thread_cpu_secs`] reports *the calling thread*. Without the marker this -/// system would drift onto a worker and the `main` series would silently become "whichever thread -/// ran the sampler" — noise shaped like a measurement, which is the most expensive kind of -/// instrument bug. -pub(super) fn sample_frame_time( - _pin_to_main_thread: NonSendMarker, - time: Res>, - mut stats: ResMut, -) { - let now = time.elapsed_secs(); +/// Sample both meters for this frame. +pub(super) fn sample_frame_time(time: Res>, mut stats: ResMut) { let wall_ms = time.delta_secs() * 1000.0; stats.wall.push(wall_ms); @@ -501,19 +119,6 @@ pub(super) fn sample_frame_time( } stats.prev_cpu_secs = cpu; - let main = main_thread_cpu_secs(); - if let (Some(prev), Some(n)) = (stats.prev_main_secs, main) { - stats.main.push(((n - prev) * 1000.0) as f32); - } - stats.prev_main_secs = main; - - stats.refresh_baselines(now); - // The first frames have no baseline worth testing against — a cold window would latch the - // startup gap as a spike and hold it for ten seconds on every launch. - if stats.wall.len() > 1 && stats.baselines.wall > 0.0 { - stats.observe(now); - } - // Log hard hitches so a load freeze is attributable from the log alone (one big stall vs many // medium ones, and roughly when). The first frame's delta is the startup gap, not a hitch. if wall_ms > HITCH_LOG_MS && stats.wall.len() > 1 { @@ -525,248 +130,35 @@ pub(super) fn sample_frame_time( mod tests { use super::*; - /// Drive the meters directly, the way a run would. Times are seconds; each tuple is one frame - /// as `(wall_ms, cpu_ms, main_ms)`. - fn feed(stats: &mut FrameStats, frames: &[(f32, f32, f32)], start_t: f32, dt: f32) -> f32 { - let mut t = start_t; - for &(wall, cpu, main) in frames { - stats.wall.push(wall); - stats.cpu.push(cpu); - stats.main.push(main); - stats.refresh_baselines(t); - if stats.wall.len() > 1 && stats.baselines.wall > 0.0 { - stats.observe(t); - } - t += dt; - } - t - } - - /// A settled 120 Hz scene must latch nothing at all — the instrument's own quiet frame. + /// The window is capped and the means are windowed: 300 quiet frames after 100 loud ones + /// must read quiet, and fps must be the reciprocal of the windowed wall mean. #[test] - fn a_settled_scene_latches_no_spike() { + fn the_windows_roll_and_the_means_are_windowed() { let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400) - .map(|i| (8.3 + (i % 3) as f32 * 0.1, 15.0, 4.0)) - .collect(); - let t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); + let loud: Vec<_> = (0..100).map(|_| (33.2, 30.0)).collect(); + let calm: Vec<_> = (0..SAMPLE_WINDOW).map(|_| (16.6, 8.0)).collect(); + let mut t = s.feed_frames(&loud, 0.0, 1.0 / 30.0); + t = s.feed_frames(&calm, t, 1.0 / 60.0); + let _ = t; + + assert_eq!(s.wall.len(), SAMPLE_WINDOW, "the window is capped"); + let cpu = s.cpu.mean().expect("cpu has samples"); assert!( - s.spike(t).is_none(), - "a flat scene must not read as a spike" - ); - } - - /// The headline case: cost doubles on the main thread while the display keeps granting 120, - /// so fps does not move at all. The pill must still catch it. - #[test] - fn a_main_thread_burst_latches_while_fps_never_moves() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - let fps_before = s.fps(); - - // Six consecutive frames of main-thread cost — 0610's burst shape — with the display - // still granting its interval, exactly the case the old pill could not see. - let burst: Vec<_> = (0..6).map(|_| (8.3, 15.0, 12.0)).collect(); - t = feed(&mut s, &burst, t, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 4.0)], t, 1.0 / 120.0); - - let spike = s - .spike(t) - .expect("a six-frame main-thread burst must latch"); - assert_eq!(spike.kind, SpikeKind::Main); - assert_eq!( - spike.frames, 6, - "the badge reports the burst, not one frame" - ); - assert!((spike.peak_ms - 12.0).abs() < 0.01); - // The control: the pill's dim fps is still, by construction, unmoved. - assert!( - (s.fps() - fps_before).abs() < 1.0, - "fps must be blind here — that is the whole reason the latch exists" - ); - } - - /// A long frame with both CPU meters flat is a stall, not our work — and must be named as one. - #[test] - fn a_long_frame_with_flat_cpu_reads_as_stalled_not_busy() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed(&mut s, &[(40.0, 15.0, 4.0)], t, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 4.0)], t, 1.0 / 120.0); - - let spike = s.spike(t).expect("a 40 ms frame must latch"); - assert_eq!(spike.kind, SpikeKind::Stalled); - } - - /// Process CPU jumping while the main thread stays flat is a worker burst, off the critical - /// path — the distinction the old all-threads-only meter could not draw. - #[test] - fn a_worker_burst_is_not_blamed_on_the_main_thread() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - let burst: Vec<_> = (0..WORKER_BURST_FRAMES).map(|_| (8.3, 60.0, 4.0)).collect(); - t = feed(&mut s, &burst, t, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 4.0)], t, 1.0 / 120.0); - - let spike = s.spike(t).expect("a worker burst must latch"); - assert_eq!(spike.kind, SpikeKind::Worker); - } - - /// The noise floor the badge kept tripping on: `cpu` sums every thread, so one frame where - /// several pool workers overlap trips the ratio test while costing the frame nothing. It must - /// not reach the pill — nor the tooltip's burst count, or the two would disagree. - #[test] - fn a_one_frame_worker_blip_does_not_latch() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 60.0, 4.0)], t, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 4.0)], t, 1.0 / 120.0); - - assert!( - s.spike(t).is_none(), - "a single-frame cross-thread CPU blip is the scheduler, not a regression" - ); - assert_eq!(s.recent_bursts(t), 0, "and it is not counted as a burst"); - } - - /// The gate is on `Worker` alone: a one-frame main-thread spike *is* the stutter and must - /// still latch immediately. - #[test] - fn a_one_frame_main_spike_is_not_gated() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 30.0)], t, 1.0 / 120.0); - t = feed(&mut s, &[(8.3, 15.0, 4.0)], t, 1.0 / 120.0); - - let spike = s.spike(t).expect("one long main-thread frame must latch"); - assert_eq!(spike.kind, SpikeKind::Main); - assert_eq!(spike.frames, 1); - } - - /// The 120 Hz calibration bug, pinned. A missed interval on a ProMotion panel is 16.7 ms; the - /// old fixed 25 ms threshold (1.5 × an assumed 60 Hz budget) could not see one. - #[test] - fn a_missed_interval_is_counted_at_120hz() { - let mut s = FrameStats::default(); - let mut frames: Vec<_> = (0..300).map(|_| (8.3, 15.0, 4.0)).collect(); - frames[150] = (16.7, 15.0, 4.0); - let _ = feed(&mut s, &frames, 0.0, 1.0 / 120.0); - - assert!( - (s.rail_ms() - 8.3).abs() < 0.2, - "the rail must be derived from the panel we are on, not assumed at 60 Hz" - ); - let (n, _) = s.wall.frames_over(s.dropped_above_ms()); - assert_eq!( - n, 1, - "the doubled frame is a missed interval and must count" - ); - // What the old rule would have said, kept as the contrast this test exists to prevent. - let (old_n, _) = s - .wall - .frames_over(super::super::FRAME_BUDGET_MS * DROPPED_FACTOR); - assert_eq!(old_n, 0, "the assumed-60 Hz threshold is blind to it"); - } - - /// The sparkline's y-scale must survive the launch spike. A loading second costs ~110 ms - /// against a settled ~8.5, and scaling to the window's MAX pressed a whole minute of real - /// signal into the bottom 7 % of the box — the lane read as a flat line on the director's - /// screen. p90 drops the outlier and keeps the shape. - #[test] - fn one_loading_second_does_not_flatten_the_trend_lane() { - let mut s = FrameStats::default(); - let mut t = 0.0; - // A loading second, then a settled minute — one trend sample per second, so step the - // clock a full second between feeds. - t = feed(&mut s, &[(111.0, 111.0, 90.0)], t, 1.0); - for _ in 0..40 { - t = feed(&mut s, &[(16.6, 8.5, 1.7)], t, 1.0); - } - assert!( - s.trend.iter().any(|v| v > 100.0), - "the loading sample is still IN the window — this is about the scale, not a filter" + (cpu - 8.0).abs() < 0.01, + "the loud prefix must have rolled out, got {cpu}" ); assert!( - s.trend_hi() < 20.0, - "p90 must ignore the launch outlier, got {}", - s.trend_hi() - ); - // The settled level has to land in a readable part of the box, not squashed at the floor. - assert!( - 8.5 / (s.trend_hi() * 1.15) > 0.5, - "the settled level must occupy the upper half of the lane" + (s.fps() - 1000.0 / 16.6).abs() < 0.5, + "fps is the windowed wall mean's reciprocal, got {}", + s.fps() ); } - /// The latch must keep the worst burst in the window, not the most recent — a small wobble - /// after a big spike must not bury it. + /// An empty cpu window is "no data", not "zero cost" — the pill prints `--` for it. #[test] - fn the_latch_keeps_the_worst_burst_not_the_last() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed( - &mut s, - &[(8.3, 15.0, 30.0), (8.3, 15.0, 4.0)], - t, - 1.0 / 120.0, - ); - t = feed( - &mut s, - &[(8.3, 15.0, 11.0), (8.3, 15.0, 4.0)], - t, - 1.0 / 120.0, - ); - - let spike = s.spike(t).expect("still inside the hold window"); - assert!( - (spike.peak_ms - 30.0).abs() < 0.01, - "the 30 ms peak must survive the 11 ms one" - ); - assert_eq!( - s.recent_bursts(t), - 2, - "both bursts are counted even though one is shown" - ); - } - - /// And it must let go: a spike outside the hold window is over. - #[test] - fn the_latch_expires() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 4.0)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed( - &mut s, - &[(8.3, 15.0, 30.0), (8.3, 15.0, 4.0)], - t, - 1.0 / 120.0, - ); - assert!(s.spike(t).is_some()); - assert!(s.spike(t + LATCH_HOLD_SECS + 0.1).is_none()); - } - - /// The floor exists so a sub-millisecond series cannot manufacture spikes out of its own - /// noise: 2× of nearly nothing is still nearly nothing. - #[test] - fn a_tiny_baseline_does_not_manufacture_spikes() { - let mut s = FrameStats::default(); - let calm: Vec<_> = (0..400).map(|_| (8.3, 15.0, 0.4)).collect(); - let mut t = feed(&mut s, &calm, 0.0, 1.0 / 120.0); - t = feed( - &mut s, - &[(8.3, 15.0, 0.9), (8.3, 15.0, 0.4)], - t, - 1.0 / 120.0, - ); - assert!( - s.spike(t).is_none(), - "0.4 -> 0.9 ms is a 2x ratio and still noise; the floor must hold it" - ); + fn no_data_is_not_zero_cost() { + let s = FrameStats::default(); + assert!(s.cpu.mean().is_none()); + assert_eq!(s.fps(), 0.0); } } diff --git a/crates/benilla-protocol/src/messages/update_object/fields/mod.rs b/crates/benilla-protocol/src/messages/update_object/fields/mod.rs index ab0f6546..8129e39d 100644 --- a/crates/benilla-protocol/src/messages/update_object/fields/mod.rs +++ b/crates/benilla-protocol/src/messages/update_object/fields/mod.rs @@ -1,4 +1,3 @@ -use std::collections::BTreeMap; use std::io::{self, Read}; use crate::wire::{read_u32_le, read_u8, Vector3d}; @@ -503,11 +502,15 @@ pub struct PlayerSkillSlot { pub perm_bonus: i16, } -/// A sparse update-field set: a bitmask of `u32` blocks followed by one `u32` per set bit. We keep the -/// values in an index→value map and expose **named** accessors for the descriptor fields consumers read -/// — the raw `get_*(index)` reads stay module-private, so field-index knowledge (a wire fact) never -/// leaves this crate (decision 0061). The ECS mirrors one of these per object and [`Self::merge`]s each -/// `Values` delta into it; the codec itself stays stateless (decision 0006). +/// A sparse update-field set: a bitmask of `u32` blocks followed by one `u32` per set bit. We keep +/// the wire's own mask plus a dense value array — not a map — because the ECS-side pollers +/// (animation, equipment, plates) probe thousands of fields **per frame**, so a read must be two +/// array indexings, never a tree walk (decision 1457); the wire's `u8` block count bounds the +/// arrays at 8160 dwords, and a Unit's real footprint is ~800 B. We expose **named** accessors for +/// the descriptor fields consumers read — the raw `get_*(index)` reads stay module-private, so +/// field-index knowledge (a wire fact) never leaves this crate (decision 0061). The ECS mirrors +/// one of these per object and [`Self::merge`]s each `Values` delta into it; the codec itself +/// stays stateless (decision 0006). /// /// **Absent-field semantics** hinge on [`Self::descriptor_end`]: a CREATE block is a *complete* /// snapshot — the server masks in only non-zero fields (vmangos `Object::_SetCreateBits`: bit set @@ -527,7 +530,13 @@ pub struct PlayerSkillSlot { /// unstreamed default `1.0` and the tooltip read `inf - inf` / `nan` (director, 2026-08-07). #[derive(Debug, Clone, Default)] pub struct ObjectFields { - fields: BTreeMap, + /// Presence bitmask, one bit per field index (`index = word * 32 + bit`) — the wire's block + /// mask, kept verbatim. + present: Vec, + /// Dense value array, invariant `values.len() == present.len() * 32`; a slot is meaningful + /// iff its `present` bit is set (unset slots hold `0` but must be read through the mask — + /// absent-vs-zero is exactly the distinction the struct doc is about). + values: Vec, /// How long this object's descriptor is, in dwords — [`descriptor_len`] of the CREATE block's /// own `ObjectType` (set by the parser via [`Self::into_created`]). Every index **below** it is /// known: absent = `0`. `0` marks a bare `Values` delta (or a hand-built fixture), where no @@ -558,20 +567,21 @@ fn descriptor_len(object_type: ObjectType) -> u16 { impl ObjectFields { pub(super) fn read(r: &mut impl Read) -> io::Result { let amount_of_blocks = read_u8(r)?; - let mut blocks = Vec::with_capacity(amount_of_blocks as usize); + let mut present = Vec::with_capacity(amount_of_blocks as usize); for _ in 0..amount_of_blocks { - blocks.push(read_u32_le(r)?); + present.push(read_u32_le(r)?); } - let mut fields = BTreeMap::new(); - for (index, block) in blocks.iter().enumerate() { - for bit in 0..32u16 { - if block & (1 << bit) != 0 { - fields.insert(index as u16 * 32 + bit, read_u32_le(r)?); + let mut values = vec![0u32; present.len() * 32]; + for (word, block) in present.iter().enumerate() { + for bit in 0..32 { + if block & (1u32 << bit) != 0 { + values[word * 32 + bit] = read_u32_le(r)?; } } } Ok(Self { - fields, + present, + values, descriptor_end: 0, }) } @@ -590,10 +600,11 @@ impl ObjectFields { /// [`Self::read`]; live code never builds fields by hand. Chain [`Self::into_created`] when /// the fixture stands in for a create snapshot. pub fn from_pairs(pairs: &[(u16, u32)]) -> Self { - Self { - fields: pairs.iter().copied().collect(), - descriptor_end: 0, + let mut this = Self::default(); + for &(index, value) in pairs { + this.insert(index, value); } + this } /// A 2-field guid: `lo | hi << 32`, present iff the low half is (the wire always sends guid @@ -639,19 +650,41 @@ impl ObjectFields { )) } + /// Whether the wire genuinely carried this field (mask bit set) — the raw presence probe + /// under every accessor, bypassing the created-store absent-is-zero fold. + fn contains(&self, index: u16) -> bool { + self.present + .get(usize::from(index / 32)) + .is_some_and(|w| w & (1u32 << (index % 32)) != 0) + } + + /// The carried value, `None` when the mask bit is unset — [`Self::contains`]'s value twin. + fn get_raw(&self, index: u16) -> Option { + self.contains(index) + .then(|| self.values[usize::from(index)]) + } + + fn insert(&mut self, index: u16, value: u32) { + let word = usize::from(index / 32); + if word >= self.present.len() { + self.present.resize(word + 1, 0); + self.values.resize(self.present.len() * 32, 0); + } + self.present[word] |= 1u32 << (index % 32); + self.values[usize::from(index)] = value; + } + fn get_guid(&self, index: u16) -> Option { - // Raw map read on purpose: a guid slot stays "present iff the low half is" even on a + // Raw read on purpose: a guid slot stays "present iff the low half is" even on a // created store — every consumer already treats a sent-empty `Some(0)` as no-guid, so the // absent-is-zero fallback would only blur the two identical cases. - let lo = self.fields.get(&index).copied()?; + let lo = self.get_raw(index)?; let hi = self.get_u32(index + 1).unwrap_or(0); Some(u64::from(lo) | (u64::from(hi) << 32)) } fn get_u32(&self, index: u16) -> Option { - self.fields - .get(&index) - .copied() + self.get_raw(index) .or((index < self.descriptor_end).then_some(0)) } fn get_f32(&self, index: u16) -> Option { @@ -693,18 +726,27 @@ impl ObjectFields { if delta.descriptor_end != 0 { *self = delta; } else { - self.fields.extend(delta.fields); + for (index, value) in delta.raw_fields() { + self.insert(index, value); + } } } /// Whether this carried no fields — the codec skips emitting an empty `Values` delta. pub fn is_empty(&self) -> bool { - self.fields.is_empty() + self.present.iter().all(|&w| w == 0) } - /// Every present `(index, value)` pair — the debug/probe affordance for descriptor - /// archaeology (named accessors stay the consumer surface; decision 0061). + /// Every present `(index, value)` pair in ascending index order — the debug/probe affordance + /// for descriptor archaeology (named accessors stay the consumer surface; decision 0061). pub fn raw_fields(&self) -> impl Iterator + '_ { - self.fields.iter().map(|(&i, &v)| (i, v)) + self.present.iter().enumerate().flat_map(move |(word, &w)| { + (0..32u16) + .filter(move |bit| w & (1u32 << bit) != 0) + .map(move |bit| { + let index = word as u16 * 32 + bit; + (index, self.values[usize::from(index)]) + }) + }) } } diff --git a/crates/benilla-protocol/src/messages/update_object/fields/player.rs b/crates/benilla-protocol/src/messages/update_object/fields/player.rs index 57bf41b6..d0a44b00 100644 --- a/crates/benilla-protocol/src/messages/update_object/fields/player.rs +++ b/crates/benilla-protocol/src/messages/update_object/fields/player.rs @@ -585,8 +585,7 @@ impl ObjectFields { /// (`x = y = 0`, the live-data norm) round-trips exactly. Consumed by the type-11 transport /// evaluator (elevators/lifts rotate their keyframe offsets through this). pub fn gameobject_rotation(&self) -> Option<[f32; 4]> { - let any_sent = - (0..4u16).any(|i| self.fields.contains_key(&(FIELD_GAMEOBJECT_ROTATION + i))); + let any_sent = (0..4u16).any(|i| self.contains(FIELD_GAMEOBJECT_ROTATION + i)); any_sent.then(|| { [ self.get_f32(FIELD_GAMEOBJECT_ROTATION).unwrap_or(0.0), @@ -612,15 +611,15 @@ impl ObjectFields { self.get_f32(FIELD_GAMEOBJECT_FACING).unwrap_or(0.0), )) } - /// Whether the wire genuinely carried **any** `GAMEOBJECT_POS_*` field — a raw map read on purpose + /// Whether the wire genuinely carried **any** `GAMEOBJECT_POS_*` field — a raw presence probe on purpose /// (like `get_guid`'s, bypassing the create block's absent-is-zero fold) so a consumer can tell /// "this GO's create never carried a position" from "it did, and it's `0.0` on some axis". A normal /// GameObject sends at least one non-zero axis virtually always; a boat/zeppelin/elevator sends /// **none** (vmangos never sets `GAMEOBJECT_POS_*` on a transport). pub fn gameobject_pos_sent(&self) -> bool { - self.fields.contains_key(&FIELD_GAMEOBJECT_POS_X) - || self.fields.contains_key(&FIELD_GAMEOBJECT_POS_Y) - || self.fields.contains_key(&FIELD_GAMEOBJECT_POS_Z) + self.contains(FIELD_GAMEOBJECT_POS_X) + || self.contains(FIELD_GAMEOBJECT_POS_Y) + || self.contains(FIELD_GAMEOBJECT_POS_Z) } /// `GAMEOBJECT_TYPE_ID` — the GameObject sub-type (DOOR/CHEST/SPELL_FOCUS/…). **Absent ⇒ `0` = /// DOOR**, not "unknown": vmangos omits a zero-valued field from the create mask (the same reason an