From fd02db1a117c9238cd05d674558df686560b1aa1 Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Wed, 19 Aug 2026 13:43:26 -0400 Subject: [PATCH 1/4] feat(perf): a real produce-to-visible latency series, measured per sample MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit v2.3.9 item C's missing half. The interim figure is `lag + render_work.p95`, valid only because the lag term is a constant, and it excludes the vblank wait, lock contention, and the time a produced frame spends waiting in the handoff. Those cannot simply be added: `work`, `lock` and `wait` are separate percentile series, and summing two p95s is not the p95 of the sum — the defect `RenderPerf::work` already 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 now measured per sample. `PresentBuffer` stamps each frame when the emulation thread publishes it; `take_into` returns that stamp; the redraw handler records `stamp.elapsed()` AFTER the present. One sample spans the whole pipeline — publish, the wait in the handoff, this redraw's work, and the blocking present that puts the frame on screen. A correction to my own earlier analysis, which said neither end-to-end figure was implementable from existing data. That was wrong for one of them: `render_total` already exists and is a single per-redraw series covering work + lock + wait, so `lag + render_total.p95` is valid arithmetic today. It measures the redraw HANDLER though, not the frame's journey — it cannot see time spent waiting in the handoff — which is why this series is still the right instrument and not merely a tidier one. Only the lock-free handoff path contributes, because it is the only path where a frame crosses a thread boundary and can therefore wait. 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. Two mutations failed to be caught, and both taught something worth writing down rather than papering over: Returning the newest publish stamp instead of the taken slot's fails NO test — because `publish` always swaps into `ready` and `take_into` always takes `ready`, so under the lock those cannot differ. My first comment claimed per-slot stamps were necessary to avoid attributing a new timestamp to an old frame. That was wrong, and the comment now says so, keeping per-slot storage for the honest reason: a 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. Clearing the stamps in `reset()` likewise fails no test, because `has_new` is cleared there and `take_into` returns before touching a stamp while it is false. Kept as defensive, and labelled as such rather than as coverage. `take_into` returns `Option` in place of `bool`; the five existing tests move from `assert!(..)` to `.is_some()` / `.is_none()` with no semantic change. Verified: fmt, workspace clippy, `emu-thread` / `debug-hooks` / `full` combos, both wasm32 invocations, rustdoc, frontend suite at 525. Co-Authored-By: Claude Opus 5 --- crates/rustynes-frontend/src/app.rs | 40 ++++++- crates/rustynes-frontend/src/perf.rs | 31 ++++++ .../rustynes-frontend/src/present_buffer.rs | 103 ++++++++++++++++-- 3 files changed, 161 insertions(+), 13 deletions(-) diff --git a/crates/rustynes-frontend/src/app.rs b/crates/rustynes-frontend/src/app.rs index 57d09566..eb4afcf7 100644 --- a/crates/rustynes-frontend/src/app.rs +++ b/crates/rustynes-frontend/src/app.rs @@ -9454,6 +9454,14 @@ 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. + #[cfg(all(not(target_arch = "wasm32"), feature = "emu-thread"))] + let mut present_stamp: Option = None; // v2.8.0 Phase 2 — display-sync regime (native): produce // exactly one emulated frame per redraw, BEFORE presenting. @@ -10104,10 +10112,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 +10483,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/perf.rs b/crates/rustynes-frontend/src/perf.rs index c70e4771..7ca85902 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 diff --git a/crates/rustynes-frontend/src/present_buffer.rs b/crates/rustynes-frontend/src/present_buffer.rs index d1747661..639652b2 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); @@ -138,14 +161,14 @@ impl PresentBuffer { /// 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 { + 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 +179,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 +199,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 +230,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)); + assert!(pb.take_into(&mut out).is_none()); assert_eq!(out, frame); } @@ -214,7 +247,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 +275,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 +333,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 +358,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 +380,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]; From dbd97fed3572fe7559518d02c3681f3a8a05669b Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Wed, 19 Aug 2026 13:54:28 -0400 Subject: [PATCH 2/4] =?UTF-8?q?docs(plans):=20correct=20item=20C=20?= =?UTF-8?q?=E2=80=94=20one=20of=20the=20two=20figures=20WAS=20implementabl?= =?UTF-8?q?e?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The plan recorded that item C was "not implementable from the data that exists". That was too strong, and found by building the thing rather than re-reading the claim. `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, which is exactly the case the constant-shift argument rescues. The original claim was right about the two figures as I had specified them and wrong about the data available to compute them. 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. Recorded as a correction beside the original reasoning rather than a rewrite, because the reasoning was sound and only its conclusion overreached — and because "I checked and it was narrower than I said" is more useful to the next reader than a page that was always right. Co-Authored-By: Claude Opus 5 --- to-dos/plans/v2.3.9-crucible-plan.md | 22 ++++++++++++++++------ 1 file changed, 16 insertions(+), 6 deletions(-) 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 From 1fd46c51c4aff7b4aac31df8ee6826d868922795 Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Wed, 19 Aug 2026 14:17:56 -0400 Subject: [PATCH 3/4] feat(frontend): the full end-to-end figure, now that a real series exists MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Completes v2.3.9 item C. The previous commit added the produce-to-visible series and stopped there — the panel still showed only the interim figure, so the measurement existed and nobody could see it. Building an instrument and not wiring it to the surface is the shape of defect this release line opened with. The panel now leads with `game delay + full pipeline` when that series has samples, and reports the render-work figure beneath it as context: "of which render work is about N ms; the rest is the frame waiting to be shown". That second clause is the point of having built the series — the gap between the two numbers IS the handoff wait, which no existing series could see. Both figures remain `constant + ONE series`, which is the only arithmetic that yields a real percentile. Neither is a sum of percentiles, and the enum carries that reasoning at the field rather than in a comment somewhere upstream. `full_ms` is an `Option`, gated on ITS OWN sample count rather than 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 this one — so borrowing the other's sufficiency would publish a percentile over a handful of samples as though it were over hundreds. `None` there means "this path produced no samples", which is neither zero nor the same as the work figure, and the panel says which. Two tests, two mutations. Making the full figure borrow the work series' sample count fails the first; making it use the work p95 fails the second, because that test asserts the full figure is strictly LARGER — the whole pipeline cannot be cheaper than one span of it. Verified: fmt, workspace clippy, `emu-thread` / `debug-hooks` / `full` combos, both wasm32 invocations, rustdoc, frontend suite at 527. Co-Authored-By: Claude Opus 5 --- crates/rustynes-frontend/src/app.rs | 1 + .../src/debugger/latency_panel.rs | 159 ++++++++++++++++-- crates/rustynes-frontend/src/debugger/mod.rs | 6 + .../src/debugger/perf_panel.rs | 13 ++ crates/rustynes-frontend/src/perf.rs | 3 + 5 files changed, 165 insertions(+), 17 deletions(-) diff --git a/crates/rustynes-frontend/src/app.rs b/crates/rustynes-frontend/src/app.rs index eb4afcf7..576ba8df 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; 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 7ca85902..d878e206 100644 --- a/crates/rustynes-frontend/src/perf.rs +++ b/crates/rustynes-frontend/src/perf.rs @@ -793,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`]. From 653bb150893ce7c19bb3cdf340e8892cc093ede4 Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Wed, 19 Aug 2026 15:55:37 -0400 Subject: [PATCH 4/4] docs(frontend): correct take_into's return contract, and drop a redundant annotation Two review findings on #412. Copilot, and it is a real defect: `take_into`'s doc comment still described a `bool` return, in a PR whose whole subject is that it now returns `Option`. A doc that contradicts its own signature is the class this release keeps finding, arriving here in the smallest possible form. Rewritten to say what the stamp IS -- the instant the emulation thread published that frame, carried per slot so it travels with the frame it describes -- and why it exists, since a per-sample total is the only way to build a distribution that summing percentiles cannot. A test comment saying "take returns false" is corrected with it. Antigravity reported a BLOCKING build failure: `present_stamp` annotated `Option` against a `web_time::Instant` return, "a distinct newtype wrapper on native targets". That is the inverse of how `web_time` works -- it re-exports std's type on native and substitutes its own only on wasm -- so the annotation compiles, which CI on this branch had already demonstrated across every feature combination before the review was posted. Its SUGGESTION is adopted anyway, for a different reason than the one given. The annotation names a second, coincidentally-equal spelling of one type, and it is correct only because this line is native-only and web_time aliases std there. Dropping it lets the type come from `take_into`, which is where it is actually decided. The comment records both the reason and the fact that the reported build failure was not real, so the next reader does not reinstate the annotation to fix a problem that never existed. --- crates/rustynes-frontend/src/app.rs | 12 +++++++++++- crates/rustynes-frontend/src/present_buffer.rs | 17 +++++++++++++---- 2 files changed, 24 insertions(+), 5 deletions(-) diff --git a/crates/rustynes-frontend/src/app.rs b/crates/rustynes-frontend/src/app.rs index 576ba8df..3b8d82a9 100644 --- a/crates/rustynes-frontend/src/app.rs +++ b/crates/rustynes-frontend/src/app.rs @@ -9461,8 +9461,18 @@ impl ApplicationHandler for App { // 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: Option = None; + let mut present_stamp = None; // v2.8.0 Phase 2 — display-sync regime (native): produce // exactly one emulated frame per redraw, BEFORE presenting. diff --git a/crates/rustynes-frontend/src/present_buffer.rs b/crates/rustynes-frontend/src/present_buffer.rs index 639652b2..a5524b1a 100644 --- a/crates/rustynes-frontend/src/present_buffer.rs +++ b/crates/rustynes-frontend/src/present_buffer.rs @@ -158,9 +158,18 @@ 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). + /// 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) { @@ -232,7 +241,7 @@ mod tests { let mut out = Vec::new(); assert!(pb.take_into(&mut out).is_some()); assert_eq!(out, frame); - // No new frame -> take returns false and leaves `out` intact. + // No new frame -> take returns `None` and leaves `out` intact. assert!(pb.take_into(&mut out).is_none()); assert_eq!(out, frame); }