diff --git a/crates/benilla-app/src/capture/mod.rs b/crates/benilla-app/src/capture/mod.rs index 01ff10b0..1a1792a8 100644 --- a/crates/benilla-app/src/capture/mod.rs +++ b/crates/benilla-app/src/capture/mod.rs @@ -124,7 +124,7 @@ pub(crate) use probes::{ JitterMeterPlugin, LiftCensusPlugin, LiveFpsPlugin, NodeProbePlugin, ParticleCensusPlugin, ProbeChatPlugin, ProbeClock, ProbeDragPlugin, ProbeExitPlugin, ProbeFocusPlugin, ProbeHoverPlugin, ProbeKeyPlugin, ProbeLuaPlugin, ProbeResizePlugin, RevealAuditPlugin, - SchedCensusPlugin, UnitVisualsPlugin, + SchedCensusPlugin, StallPlugin, TrailCensusPlugin, UnitVisualsPlugin, }; use scenarios::GlueScreen; use scenarios::{Scenario, SubjectKind, UiFixture, GLUE_SCENARIOS, GROUND_EYE, SCENARIOS}; diff --git a/crates/benilla-app/src/capture/probes/mod.rs b/crates/benilla-app/src/capture/probes/mod.rs index 6dc68384..f9a3e66d 100644 --- a/crates/benilla-app/src/capture/probes/mod.rs +++ b/crates/benilla-app/src/capture/probes/mod.rs @@ -41,6 +41,8 @@ pub(crate) use ground_census::GroundCensusPlugin; /// never armed and so never lifted its spawn-hide (B168). mod lift_census; pub(crate) use lift_census::LiftCensusPlugin; +mod trail_census; +pub(crate) use trail_census::TrailCensusPlugin; /// The unit-visual census — per-entity "what visual did this display actually get", which is what /// separates a debug cube (a gap of ours) from a model that legitimately draws nothing (B13, @@ -76,6 +78,12 @@ pub(crate) use world_census::{EntityCensusPlugin, NodeProbePlugin}; mod sched_census; pub(crate) use sched_census::SchedCensusPlugin; +/// The frame-stall injector — blocks the main loop on a schedule, reproducing on demand the one +/// thing a probe window can never do to itself: go to the background and come back with one +/// enormous frame delta. Doubles as the plain frame-delta/occlusion monitor at `WOW_STALL=0`. +mod stall; +pub(crate) use stall::StallPlugin; + /// The clock **every probe schedule reads** — real time, never the virtual clock (decision 0789). /// /// A probe knob is a wall-clock instruction: "send this at 20 s", "sample 300 frames from 25 s", @@ -127,6 +135,13 @@ mod tests { "the fixture AGE runs on the clock the effect animates on, and the capture freezes \ that same clock at save time — an age, not a schedule", ), + ( + "capture/probes/stall.rs", + "drive_stall", + "the clamp IS the subject: this probe reports `Time`'s delta beside \ + `Time`'s so a stalled frame's divergence is a printed number rather than a \ + remembered constant. Its own schedule is [`ProbeClock`], bound on the line above", + ), ( "capture/waterfx.rs", "spawn / drive", diff --git a/crates/benilla-app/src/capture/probes/stall.rs b/crates/benilla-app/src/capture/probes/stall.rs new file mode 100644 index 00000000..671ddd92 --- /dev/null +++ b/crates/benilla-app/src/capture/probes/stall.rs @@ -0,0 +1,237 @@ +//! The **frame-stall injector** (`WOW_STALL="[,[,[,]]]"`) — the +//! instrument that makes "I tabbed away and came back to X" reproducible. +//! +//! A probe window cannot be tabbed away from: every scripted live probe asserts `AlwaysOnTop` +//! ([`super::ProbeFocusPlugin`], decision 0906) precisely so the OS cannot throttle it. So the one +//! class of bug that only appears *because* the window went to the background — the client running +//! for seconds at ~1 fps and then resuming — had no reproduction at all. This is that reproduction: +//! it blocks the main loop for `` on each of `` consecutive frames, every `` +//! seconds, starting at ``. Nothing else. +//! +//! **What backgrounding actually does, and why this shape is the faithful one.** Two independent +//! mechanisms, and only the second one bites: +//! +//! - *winit* — we never set [`bevy::winit::WinitSettings`], so we get its `Default`, which is +//! `WinitSettings::game()`: `focused_mode: Continuous`, `unfocused_mode: +//! reactive_low_power(1/60 s)` (`bevy_winit-0.18.1/src/winit_config.rs:19-22`). An unfocused +//! window therefore still targets **60 Hz**; losing focus on its own costs nothing. +//! - *macOS* — a window that is fully **covered** is throttled at the drawable: every +//! `CAMetalLayer.nextDrawable` blocks about a second, so the run continues at ~1 fps for as long +//! as it is covered (decisions 0713/0777; the director's correction in 0906 — "any covering +//! window, not just the lock screen"; 1355 measured the signature as a `p99 ≈ 1020 ms` +//! metronome). A ten-second glance at a terminal is therefore ~10 consecutive one-second frames, +//! which is why `` exists: a *single* long frame is a hitch, and a hitch is not what +//! backgrounding does. +//! +//! So the knob that reproduces a ten-second tab-away is `WOW_STALL="1000,20,60,10"`. +//! +//! **Not to be confused with `WOW_STALL_INJECT`** (`crate::perf::stall`, decisions 0713/1637), +//! whose name is one suffix away. That one fires **a single** sleep at a single instant, and it +//! exists to prove the stuck-main-thread *watchdog* fires — it is a test affordance for an +//! instrument, not a reproduction of a gameplay state. This one repeats, blocks `` in a +//! row, and carries the frame-delta/occlusion monitor, which is the whole difference: 1663 was +//! reproducible only with **consecutive** long frames (one alone loses the deck for a frame and +//! recovers; two drop the rider through it). The two should probably become one knob — flagged, +//! not done here. +//! +//! **`WOW_STALL="0"` injects nothing** and leaves only the monitor running — the "what is this +//! run's frame pacing actually doing" reader, which is how the premise above gets checked on a real +//! run instead of assumed. Every run prints, per window: +//! +//! ```text +//! STALL_WATCH t=35.0 frames=299 p50=16.7 p99=17.9 max=33.4 focused=1 occluded=0 +//! STALL t=35.0 sleeping 1000 ms (1/10) +//! STALL_HIT t=36.0 injected=1000 wall_dt=1016.4 real_dt=16.7 virt_dt=16.7 clamped=0 +//! ``` +//! +//! **Three clocks on that line, and they are three different clocks — that is the point.** +//! +//! - `wall_dt` is [`Instant`] to [`Instant`] across the main-schedule pass: the true frame time, +//! and the clock `transport::Transport::cycle_ms` runs on (`anchor.at.elapsed()`). +//! - `real_dt` is `Time`'s delta, which under pipelined rendering is **not** the wall clock: +//! `time_system` stamps it from an `Instant` the *render world* sends over a `bounded(2)` channel +//! (`bevy_time-0.18.1/src/lib.rs:152-171`, `bevy_render-0.18.1/src/renderer/mod.rs:113`), so it +//! arrives a frame or two late — bevy's own source carries a `TODO: Figure out how to handle +//! this when using pipelined rendering` right above it. +//! - `virt_dt` is what every consumer of `Res