diff --git a/crates/rustynes-frontend/src/app.rs b/crates/rustynes-frontend/src/app.rs index 57d09566..3b8d82a9 100644 --- a/crates/rustynes-frontend/src/app.rs +++ b/crates/rustynes-frontend/src/app.rs @@ -7275,6 +7275,7 @@ impl App { perf_view.render_work = r.work; perf_view.render_lock = r.lock; perf_view.render_cpu = r.cpu; + perf_view.present_lat = r.present_lat; #[cfg(feature = "debug-hooks")] { perf_view.lock_gap_hits = r.lock_gap_hits; @@ -9454,6 +9455,24 @@ impl ApplicationHandler for App { // builds once already this release). Fully qualified because the // `Duration` import is itself native-only. let mut lock_wait = std::time::Duration::ZERO; + // v2.3.9 item C — publish stamp of the frame this redraw will show. + // Declared in the same scope as `lock_wait` and for the same reason: + // it is set inside one render branch and consumed after the present, + // so a narrower scope would not reach `record_redraw`. Set only on + // the lock-free handoff path — the only path where a frame crosses a + // thread boundary and can therefore wait. + // + // Deliberately UNANNOTATED. The type comes from `take_into`, + // which returns `web_time::Instant` — the crate's Instant + // everywhere in this file. Writing `Option` + // here compiles only because `web_time` re-exports std's type on + // native, and this line is native-only; naming std's type would + // be a second, coincidentally-equal spelling of one thing. + // (Review on #412 proposed the inference form. Its stated reason + // was that the annotation fails to build — it does not — but the + // suggestion is right for this reason instead.) + #[cfg(all(not(target_arch = "wasm32"), feature = "emu-thread"))] + let mut present_stamp = None; // v2.8.0 Phase 2 — display-sync regime (native): produce // exactly one emulated frame per redraw, BEFORE presenting. @@ -10104,10 +10123,20 @@ impl ApplicationHandler for App { // frame arrived; otherwise keep the previously presented // staging (the display simply re-presents it). #[cfg(all(not(target_arch = "wasm32"), feature = "emu-thread"))] - if !self.present_buffer.take_into(&mut self.present_staging) - && self.present_staging.is_empty() { - self.present_staging.resize((NES_W * NES_H * 4) as usize, 0); + // v2.3.9 — the publish stamp of the frame this redraw + // will show, carried to the end of the handler so the + // recorded latency spans produce -> VISIBLE rather than + // produce -> taken. `None` when nothing new arrived, in + // which case this redraw re-presents the previous frame + // and contributes no sample: its age would be measured + // from a publish two redraws ago and describe the + // display's cadence rather than the pipeline's latency. + let taken = self.present_buffer.take_into(&mut self.present_staging); + present_stamp = taken; + if taken.is_none() && self.present_staging.is_empty() { + self.present_staging.resize((NES_W * NES_H * 4) as usize, 0); + } } } else { let mut guard = self.emu.lock_timed(&mut lock_wait); @@ -10465,6 +10494,22 @@ impl ApplicationHandler for App { lock_wait, cpu_span, ); + // v2.3.9 item C — produce -> VISIBLE latency, as ONE sample. + // + // Recorded here, after the present, so the sample spans the + // whole pipeline: the frame's publish on the emulation thread, + // its wait in the handoff, this redraw's work, and the blocking + // present that puts it on screen. + // + // One series rather than a sum of `work`, `lock` and `wait`, + // because summing percentiles is not the percentile of the sum + // — the same defect `RenderPerf::work` exists to avoid, in the + // addition direction. A distribution has to be built from + // per-sample totals, which is what this is. + #[cfg(all(not(target_arch = "wasm32"), feature = "emu-thread"))] + if let Some(published) = present_stamp { + self.render_perf.record_present_latency(published.elapsed()); + } } match render_result { Ok(()) => { diff --git a/crates/rustynes-frontend/src/debugger/latency_panel.rs b/crates/rustynes-frontend/src/debugger/latency_panel.rs index e6571fa1..55932ac6 100644 --- a/crates/rustynes-frontend/src/debugger/latency_panel.rs +++ b/crates/rustynes-frontend/src/debugger/latency_panel.rs @@ -205,6 +205,7 @@ pub fn show( nes: Option<&mut Nes>, current_run_ahead: u32, render_work: crate::perf::IntervalStats, + present_lat: crate::perf::IntervalStats, ) { let can_measure = nes.is_some(); super::detachable_window( @@ -217,7 +218,16 @@ pub fn show( ..Default::default() }, open, - |ui| body(ui, state, can_measure, current_run_ahead, render_work), + |ui| { + body( + ui, + state, + can_measure, + current_run_ahead, + render_work, + present_lat, + ); + }, ); // Measure AFTER the render — `nes` is free here, not captured by any closure. if std::mem::take(&mut state.measure_requested) { @@ -232,6 +242,7 @@ fn body( can_measure: bool, current: u32, render_work: crate::perf::IntervalStats, + present_lat: crate::perf::IntervalStats, ) { ui.label("Measures how many frames this game waits before acting on input."); ui.weak( @@ -268,6 +279,7 @@ fn body( current, state.frame_ms, render_work, + present_lat, &mut state.pending_apply, ); } @@ -285,6 +297,7 @@ fn report_body( current: u32, frame_ms: f64, render_work: crate::perf::IntervalStats, + present_lat: crate::perf::IntervalStats, pending_apply: &mut Option, ) { if let Some(frames) = report.frames { @@ -299,7 +312,7 @@ fn report_body( // copied from and ran every PAL cartridge fast. (PR #385 review.) let ms = f64::from(frames) * frame_ms; ui.weak(format!("about {ms:.0} ms of the game's own delay")); - end_to_end(ui, frames, current, frame_ms, render_work); + end_to_end(ui, frames, current, frame_ms, render_work, present_lat); let confidence = match report.confidence { Confidence::Unanimous => "every reacting button agreed", @@ -407,23 +420,49 @@ fn end_to_end( current_run_ahead: u32, frame_ms: f64, render_work: crate::perf::IntervalStats, + present_lat: crate::perf::IntervalStats, ) { - match end_to_end_figure(frames, current_run_ahead, frame_ms, render_work) { + match end_to_end_figure( + frames, + current_run_ahead, + frame_ms, + render_work, + present_lat, + ) { EndToEnd::Unavailable { samples, need } => { ui.weak(format!( "end-to-end unavailable: {samples} render samples, need {need}" )); } - EndToEnd::Ms { total, effective } => { - ui.label(format!( - "Game delay + render work: about {total:.0} ms (p95)" - )); + EndToEnd::Ms { + work_ms, + full_ms, + effective, + } => { + if let Some(full) = full_ms { + // The complete figure leads where it exists: it is what the user + // actually waits. The narrower one becomes context for it. + ui.label(format!( + "Game delay + full pipeline: about {full:.0} ms (p95)" + )); + ui.weak(format!( + "of which render work is about {work_ms:.0} ms; the rest is the \ + frame waiting to be shown" + )); + } else { + ui.label(format!( + "Game delay + render work: about {work_ms:.0} ms (p95)" + )); + ui.weak( + "Excludes the vblank wait and the frame's wait to be shown — \ + that series has no samples on this path.", + ); + } if current_run_ahead > 0 { ui.weak(format!( "{effective} of {frames} frames remain after run-ahead {current_run_ahead}" )); } - ui.weak("Excludes the vblank wait and lock contention — see the panel docs."); } } } @@ -442,7 +481,21 @@ enum EndToEnd { /// Too few render samples for a percentile to mean anything. Unavailable { samples: usize, need: usize }, /// Milliseconds, with the frame count left after run-ahead. - Ms { total: f64, effective: u32 }, + Ms { + /// Game delay + render WORK. Excludes the vblank wait and lock + /// contention, which are separate percentile series. + work_ms: f64, + /// Game delay + the whole produce-to-visible pipeline, when that series + /// has samples. + /// + /// `None` is neither "zero" nor "same as `work_ms`": the + /// produce-to-visible series only fills on the lock-free handoff path, + /// so a configuration that never takes it has nothing to report and + /// says so. + full_ms: Option, + /// Frames of the game's own lag left after run-ahead. + effective: u32, + }, } fn end_to_end_figure( @@ -450,6 +503,7 @@ fn end_to_end_figure( current_run_ahead: u32, frame_ms: f64, render_work: crate::perf::IntervalStats, + present_lat: crate::perf::IntervalStats, ) -> EndToEnd { if render_work.count < MIN_RENDER_SAMPLES { return EndToEnd::Unavailable { @@ -462,8 +516,16 @@ fn end_to_end_figure( // worst exactly when they have taken this panel's advice. Saturating, not // wrapping: a depth above the measured lag leaves zero, not `u32::MAX`. let effective = frames.saturating_sub(current_run_ahead); + let lag_ms = f64::from(effective) * frame_ms; EndToEnd::Ms { - total: f64::from(effective) * frame_ms + f64::from(render_work.p95_ms), + work_ms: lag_ms + f64::from(render_work.p95_ms), + // Gated on its OWN sample count, not on `render_work`'s. The two series + // fill from different paths — every redraw feeds `work`, only a redraw + // that took a new frame from the handoff feeds this one — so borrowing + // the other's sufficiency would report a percentile over a handful of + // samples as though it were over hundreds. + full_ms: (present_lat.count >= MIN_RENDER_SAMPLES) + .then(|| lag_ms + f64::from(present_lat.p95_ms)), effective, } } @@ -617,7 +679,13 @@ mod tests { #[test] fn too_few_render_samples_declines_rather_than_guessing() { assert_eq!( - end_to_end_figure(4, 0, 16.639, work(MIN_RENDER_SAMPLES - 1, 3.0)), + end_to_end_figure( + 4, + 0, + 16.639, + work(MIN_RENDER_SAMPLES - 1, 3.0), + work(0, 0.0) + ), EndToEnd::Unavailable { samples: MIN_RENDER_SAMPLES - 1, need: MIN_RENDER_SAMPLES, @@ -630,7 +698,11 @@ mod tests { /// constant — which is why a second series may never be added here. #[test] fn the_figure_is_lag_plus_one_series() { - let EndToEnd::Ms { total, effective } = end_to_end_figure(4, 0, 16.0, work(600, 3.5)) + let EndToEnd::Ms { + work_ms: total, + effective, + .. + } = end_to_end_figure(4, 0, 16.0, work(600, 3.5), work(0, 0.0)) else { panic!("expected a figure"); }; @@ -641,20 +713,69 @@ mod tests { ); } + /// The full figure is gated on ITS OWN sample count, not the work series'. + /// + /// The two fill from different paths — every redraw feeds `work`, only a + /// redraw that took a new frame from the handoff feeds `present_lat` — so + /// borrowing the other's sufficiency would publish a percentile over a + /// handful of samples as though it were over hundreds. + #[test] + fn the_full_figure_needs_its_own_samples() { + // Plenty of render-work samples, almost none of the pipeline series. + let EndToEnd::Ms { + work_ms, full_ms, .. + } = end_to_end_figure( + 2, + 0, + 16.0, + work(600, 4.0), + work(MIN_RENDER_SAMPLES - 1, 9.0), + ) + else { + panic!("expected a figure"); + }; + assert!((work_ms - 36.0).abs() < 1e-6, "2 frames + 4 ms work"); + assert!( + full_ms.is_none(), + "the full figure must not borrow the work series' sample count" + ); + } + + /// With samples of its own, the full figure is the lag plus the WHOLE + /// pipeline — and it is a different number from the work figure, which is + /// the entire reason both are reported. + #[test] + fn the_full_figure_covers_more_than_render_work() { + let EndToEnd::Ms { + work_ms, full_ms, .. + } = end_to_end_figure(2, 0, 16.0, work(600, 4.0), work(600, 9.0)) + else { + panic!("expected a figure"); + }; + let full = full_ms.expect("the pipeline series has samples"); + assert!((work_ms - 36.0).abs() < 1e-6); + assert!((full - 41.0).abs() < 1e-6, "2 frames + 9 ms pipeline"); + assert!( + full > work_ms, + "the whole pipeline cannot be cheaper than one span of it" + ); + } + /// Run-ahead removes frames of the game's own lag, so the figure must shrink /// by exactly one frame per depth — otherwise the panel overstates latency /// worst for the users who took its advice. #[test] fn run_ahead_is_subtracted_frame_for_frame() { let (base, with_two) = ( - end_to_end_figure(4, 0, 16.0, work(600, 0.0)), - end_to_end_figure(4, 2, 16.0, work(600, 0.0)), + end_to_end_figure(4, 0, 16.0, work(600, 0.0), work(0, 0.0)), + end_to_end_figure(4, 2, 16.0, work(600, 0.0), work(0, 0.0)), ); let ( - EndToEnd::Ms { total: a, .. }, + EndToEnd::Ms { work_ms: a, .. }, EndToEnd::Ms { - total: b, + work_ms: b, effective, + .. }, ) = (base, with_two) else { @@ -670,7 +791,11 @@ mod tests { /// A depth ABOVE the measured lag leaves zero, never a wrapped `u32::MAX`. #[test] fn run_ahead_deeper_than_the_lag_saturates_at_zero() { - let EndToEnd::Ms { total, effective } = end_to_end_figure(1, 3, 16.0, work(600, 2.0)) + let EndToEnd::Ms { + work_ms: total, + effective, + .. + } = end_to_end_figure(1, 3, 16.0, work(600, 2.0), work(0, 0.0)) else { panic!("expected a figure"); }; diff --git a/crates/rustynes-frontend/src/debugger/mod.rs b/crates/rustynes-frontend/src/debugger/mod.rs index e20916ac..b8dac5f4 100644 --- a/crates/rustynes-frontend/src/debugger/mod.rs +++ b/crates/rustynes-frontend/src/debugger/mod.rs @@ -2244,6 +2244,11 @@ impl DebuggerOverlay { { self.latency_ui.restore_remembered(remembered); } + // v2.3.9 item C — the produce-to-visible series, from the same + // snapshot. Passed separately rather than folded into `render_work` + // because the two answer different questions and have different + // sample populations; the panel gates each on its own count. + let present_lat = self.perf_ui.present_lat(); latency_panel::show( ctx, &mut self.detached_panels, @@ -2252,6 +2257,7 @@ impl DebuggerOverlay { nes.as_deref_mut(), current, render_work, + present_lat, ); if let Some(depth) = self.latency_ui.take_pending_apply() { config.input.run_ahead = depth; diff --git a/crates/rustynes-frontend/src/debugger/perf_panel.rs b/crates/rustynes-frontend/src/debugger/perf_panel.rs index fc971ebd..9bcf6268 100644 --- a/crates/rustynes-frontend/src/debugger/perf_panel.rs +++ b/crates/rustynes-frontend/src/debugger/perf_panel.rs @@ -48,6 +48,19 @@ impl PerfPanelState { /// `render_lock` or `render_wait` would be summing two percentiles, which is /// not the percentile of the sum — the error `RenderPerf::work` already /// exists to avoid, in the addition direction. + /// v2.3.9 item C — the produce-to-visible latency series. + /// + /// The full-pipeline counterpart of [`Self::render_work`], and offered for + /// the same reason `render_wait` and `render_lock` are NOT: this is a single + /// per-sample series, so adding it to a constant yields a real percentile. + /// It is what `work` could not be — the whole journey rather than one span + /// of it — because it is measured per frame rather than assembled from + /// parts. + #[must_use] + pub const fn present_lat(&self) -> crate::perf::IntervalStats { + self.view.present_lat + } + #[must_use] pub const fn render_work(&self) -> crate::perf::IntervalStats { self.view.render_work diff --git a/crates/rustynes-frontend/src/perf.rs b/crates/rustynes-frontend/src/perf.rs index c70e4771..d878e206 100644 --- a/crates/rustynes-frontend/src/perf.rs +++ b/crates/rustynes-frontend/src/perf.rs @@ -245,6 +245,23 @@ pub struct RenderPerf { /// observations were taken (a ROM is loaded and the arm ran twice). #[cfg(feature = "debug-hooks")] lock_gap_obs: u64, + /// v2.3.9 item C — produce-to-visible latency, one sample per presented + /// frame: from the emulation thread publishing the frame into the handoff to + /// the present that puts it on screen. + /// + /// **A real series, not a sum.** The end-to-end figure needs `work + lock + + /// wait` plus the frame's wait in the handoff, and those are separate + /// percentile series — adding two p95s is not the p95 of the sum, the same + /// defect `work` exists to avoid, in the addition direction rather than the + /// subtraction one. A distribution can only be built from per-sample totals, + /// so the total is measured per sample. + /// + /// Only the lock-free handoff path contributes. That is the only path where + /// a frame crosses a thread boundary and can therefore wait; on the + /// lock-holding path the frame is copied and presented inside one redraw, + /// so there is no queueing to measure and a sample would describe something + /// else. + present_lat: SampleRing, /// v2.3.3 — CPU time actually CONSUMED across the `work` span. /// /// `work` is wall time, so it cannot tell 27 ms of computation from 27 ms @@ -279,6 +296,8 @@ pub struct RenderStats { pub total: IntervalStats, /// Blocking present alone. pub wait: IntervalStats, + /// v2.3.9 — produce-to-visible latency, one sample per presented frame. + pub present_lat: IntervalStats, /// `total - wait - lock`. pub work: IntervalStats, /// Emulator-mutex blocking on the winit thread. @@ -346,6 +365,7 @@ impl RenderPerf { work: self.work.stats(), lock: self.lock.stats(), cpu: self.cpu.stats(), + present_lat: self.present_lat.stats(), #[cfg(feature = "debug-hooks")] lock_gap_hits: self.lock_gap_hits, #[cfg(feature = "debug-hooks")] @@ -353,6 +373,16 @@ impl RenderPerf { } } + /// v2.3.9 item C — record one presented frame's produce-to-visible latency. + /// + /// Called only when this redraw actually took a NEW frame from the handoff. + /// A redraw that re-presents the previous frame contributes nothing: its age + /// would be measured from a publish two redraws ago and would describe the + /// display's cadence rather than the pipeline's latency. + pub fn record_present_latency(&mut self, d: Duration) { + self.present_lat.push(d.as_secs_f32() * 1000.0); + } + /// v2.3.9 item B — record one redraw's two-acquisition observation. /// /// `advanced` is whether `Nes::cycle()` differed between the framebuffer @@ -384,6 +414,7 @@ impl RenderPerf { self.work.clear(); self.lock.clear(); self.cpu.clear(); + self.present_lat.clear(); // v2.3.9 — and the lock-gap counters, for exactly the reason the `wait` // comment above gives. A rate is a ratio over a population; carrying the // numerator and denominator across a ROM change or a pacing-regime @@ -762,6 +793,9 @@ pub struct PerfView { /// Denominator for [`Self::lock_gap_hits`]. #[cfg(feature = "debug-hooks")] pub lock_gap_obs: u64, + /// v2.3.9 item C — produce-to-visible latency, one sample per presented + /// frame. See [`RenderPerf`]. + pub present_lat: IntervalStats, /// v2.3.3 — egui shell build cost (winit thread). See [`RenderPerf`]. pub render_ui: IntervalStats, /// v2.3.3 — GPU encode + present cost (winit thread). See [`RenderPerf`]. diff --git a/crates/rustynes-frontend/src/present_buffer.rs b/crates/rustynes-frontend/src/present_buffer.rs index d1747661..a5524b1a 100644 --- a/crates/rustynes-frontend/src/present_buffer.rs +++ b/crates/rustynes-frontend/src/present_buffer.rs @@ -40,6 +40,7 @@ use std::sync::Arc; use std::sync::Mutex; use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; +use web_time::Instant; /// NES framebuffer size in bytes (256 × 240 × RGBA8). const FB_LEN: usize = 256 * 240 * 4; @@ -47,6 +48,24 @@ const FB_LEN: usize = 256 * 240 * 4; /// The three reusable byte buffers behind the handoff. struct Slots { bufs: [Vec; 3], + /// v2.3.9 — when each slot's frame was published, parallel to `bufs`. + /// + /// **Per slot, though a single "latest publish" field would currently give + /// the same answer** — and that is worth stating rather than dressing up as + /// necessity, because the first draft of this comment claimed the opposite. + /// `publish` always swaps `back` into `ready`, and `take_into` always takes + /// `ready`, so under the slots lock the frame taken IS the newest published. + /// A mutation returning `stamps.iter().max()` instead of `stamps[ready]` + /// fails no test, because the two cannot differ today. + /// + /// Kept per slot anyway, for the same reason `bufs` is: the timestamp is a + /// property OF the frame, so it travels with it and stays correct if the + /// handoff ever hands back something other than the newest slot. The cost is + /// three `Option`. + /// + /// `None` until a slot has been published into, so the first take cannot + /// produce an age measured from an arbitrary zero. + stamps: [Option; 3], /// `front | (ready << 2) | (back << 4)` slot ids; mutated only by the /// producer's `publish` and the consumer's `take_into` via a swap that /// keeps the three fields a permutation of `{0,1,2}`. Stored here (a plain @@ -87,6 +106,7 @@ impl PresentBuffer { generation: AtomicUsize::new(0), slots: Mutex::new(Slots { bufs: [Vec::new(), Vec::new(), Vec::new()], + stamps: [None; 3], index: Self::INIT_INDEX, }), }) @@ -125,6 +145,9 @@ impl PresentBuffer { // the same slots lock, so the index move, the slot write, and the // fresh-flag stay consistent for the consumer (which also takes the // lock before reading any of them). + // Stamped under the same lock as the copy and the index move, so a + // consumer can never observe a slot whose bytes and timestamp disagree. + slots.stamps[back] = Some(Instant::now()); let front = Self::front(idx); let ready = Self::ready(idx); slots.index = Self::pack(front, back, ready); @@ -135,17 +158,26 @@ impl PresentBuffer { /// Consumer: if a new frame was published since the last call, swap it /// into the front slot and copy it into `out` (the present-staging buffer - /// the GPU uploads). Returns `true` when `out` was refreshed with a new - /// frame, `false` when there was nothing new (the caller keeps the - /// previously presented `out` — the display simply re-presents it). - pub fn take_into(&self, out: &mut Vec) -> bool { + /// the GPU uploads). + /// + /// Returns `Some(stamp)` when `out` was refreshed, where `stamp` is the + /// instant the emulation thread **published that frame** — carried per slot + /// so it travels with the frame it describes. Returns `None` when there was + /// nothing new, in which case the caller keeps the previously presented + /// `out` and the display simply re-presents it. + /// + /// The stamp is what makes a produce-to-visible measurement a real + /// distribution: the consumer records `stamp.elapsed()` after the present, + /// so one sample spans the whole pipeline rather than being assembled by + /// summing percentiles of its parts. + pub fn take_into(&self, out: &mut Vec) -> Option { // Cheap pre-check off the lock; the authoritative check is under it. if !self.has_new.load(Ordering::Relaxed) { - return false; + return None; } let mut slots = self.slots.lock().expect("present buffer slots"); if !self.has_new.swap(false, Ordering::Relaxed) { - return false; + return None; } let idx = slots.index; let front = Self::front(idx); @@ -156,7 +188,7 @@ impl PresentBuffer { slots.index = Self::pack(ready, front, back); out.clear(); out.extend_from_slice(&slots.bufs[ready]); - true + slots.stamps[ready] } /// True once at least one frame has been published (so the present path @@ -176,6 +208,16 @@ impl PresentBuffer { for b in &mut slots.bufs { b.clear(); } + // v2.3.9 — clear the publish stamps with the buffers. + // + // Defensive, and unreachable today: `has_new` is cleared above, and + // `take_into` returns before touching a stamp while it is false, so a + // stale stamp cannot currently be observed. Verified by mutation — + // deleting this line fails nothing. Kept because the invariant it + // maintains ("a stamp describes a frame in this session") is cheaper to + // hold than to re-derive, and because a future take path that does not + // gate on `has_new` would otherwise report a latency spanning a ROM load. + slots.stamps = [None; 3]; } /// Expected framebuffer byte length (for the no-ROM black frame). @@ -197,10 +239,10 @@ mod tests { pb.publish(&frame); assert!(pb.has_published()); let mut out = Vec::new(); - assert!(pb.take_into(&mut out)); + assert!(pb.take_into(&mut out).is_some()); assert_eq!(out, frame); - // No new frame -> take returns false and leaves `out` intact. - assert!(!pb.take_into(&mut out)); + // No new frame -> take returns `None` and leaves `out` intact. + assert!(pb.take_into(&mut out).is_none()); assert_eq!(out, frame); } @@ -214,7 +256,7 @@ mod tests { // overwritten in the back slot before a take) — the intended // "drop stale frames" behavior under wall-clock pacing. let mut out = Vec::new(); - assert!(pb.take_into(&mut out)); + assert!(pb.take_into(&mut out).is_some()); assert_eq!(out, vec![4u8; 8]); } @@ -242,6 +284,56 @@ mod tests { } } + /// A stamp advances with the frame it describes. + /// + /// Note what this does NOT establish: that the stamp comes from the taken + /// slot rather than from the newest publish. Those cannot differ here — + /// `publish` swaps into `ready` and `take_into` takes `ready` — so no test + /// can separate them, and a mutation swapping one for the other passes. + /// See the `stamps` field comment. + #[test] + fn the_stamp_belongs_to_the_frame_that_was_taken() { + let pb = PresentBuffer::new(); + let mut out = Vec::new(); + + pb.publish(&vec![1u8; FB_LEN]); + let first = pb + .take_into(&mut out) + .expect("a published frame has a stamp"); + + // Two more publishes with a measurable gap, none of them taken yet. + std::thread::sleep(std::time::Duration::from_millis(5)); + pb.publish(&vec![2u8; FB_LEN]); + std::thread::sleep(std::time::Duration::from_millis(5)); + pb.publish(&vec![3u8; FB_LEN]); + + let latest = pb + .take_into(&mut out) + .expect("the freshest frame has a stamp"); + assert_eq!(out[0], 3, "premise: the freshest frame is the one taken"); + assert!( + latest > first, + "the stamp must advance with the frame it describes" + ); + } + + /// A take with nothing new returns `None` rather than a stale stamp. A + /// redraw that re-presents the previous frame must contribute no sample: + /// its age would be measured from a publish two redraws ago and would + /// describe the display's cadence rather than the pipeline's latency. + #[test] + fn an_empty_take_yields_no_stamp() { + let pb = PresentBuffer::new(); + let mut out = Vec::new(); + assert!(pb.take_into(&mut out).is_none(), "nothing published yet"); + pb.publish(&vec![7u8; FB_LEN]); + assert!(pb.take_into(&mut out).is_some()); + assert!( + pb.take_into(&mut out).is_none(), + "a second take with nothing new must not re-report the old stamp" + ); + } + #[test] fn reset_clears_published_state() { let pb = PresentBuffer::new(); @@ -250,7 +342,7 @@ mod tests { pb.reset(); assert!(!pb.has_published()); let mut out = Vec::new(); - assert!(!pb.take_into(&mut out)); + assert!(pb.take_into(&mut out).is_none()); } #[test] @@ -275,7 +367,7 @@ mod tests { let mut out = Vec::new(); let mut taken = 0u32; loop { - if pb.take_into(&mut out) { + if pb.take_into(&mut out).is_some() { taken += 1; // Every taken frame is a full 64-byte uniform buffer (no torn // read across slots). @@ -297,7 +389,7 @@ mod tests { // branch ended with `taken == 0` and failed the assert.) This // guarantees `taken >= 1` whenever the producer published at // least once, independent of how the two threads interleave. - if pb.take_into(&mut out) { + if pb.take_into(&mut out).is_some() { taken += 1; assert_eq!(out.len(), 64); let v = out[0]; diff --git a/to-dos/plans/v2.3.9-crucible-plan.md b/to-dos/plans/v2.3.9-crucible-plan.md index 6ea8698a..b9491512 100644 --- a/to-dos/plans/v2.3.9-crucible-plan.md +++ b/to-dos/plans/v2.3.9-crucible-plan.md @@ -405,12 +405,22 @@ Scoped here rather than left implicit, and explicitly lower priority than A5/B: the addition direction rather than the subtraction one. The constant-shift argument rescues exactly one series, and both figures need two or three. - **So item C is not implementable from the data that exists**, and the note it - was carried forward on ("the frontend pipeline cost `perf.rs` already tracks") - is wrong about "already". What is missing is a **single per-redraw series** — - end-to-end pipeline latency recorded as one sample per redraw and percentiled - as one distribution. That is an addition to `RenderPerf`, not a panel change, - and it is the actual first step. + **This said "item C is not implementable from the data that exists". That was + too strong, and the correction matters.** `render_total` already exists and is + a single per-redraw series covering work + lock + wait, so + `lag + render_total.p95` is valid arithmetic today — a constant plus ONE + series. The claim was right about the two figures as specified, and wrong about + the data. + + What `render_total` cannot see is the time a produced frame spends **waiting in + the handoff** before a redraw picks it up: it measures the redraw HANDLER, not + the frame's journey. Under the triple buffer those are different quantities, + and the second is what "end-to-end" means. + + So the new series is still the right instrument rather than merely a tidier + one — produce-to-visible latency, stamped at publish and recorded after the + present, one sample per presented frame. An addition to `RenderPerf`, not a + panel change. **Landed** in `PresentBuffer` + `RenderPerf::present_lat`. A cheaper interim that does not lie: report `lag_ms + render_work_p95` alone, labelled as *game delay plus render work*, and say plainly that the vblank wait