feat(perf): measure the two-acquisition race, and land the apt fix #408 missed

.github/scripts/apt-install-retry.sh

@@ -41,9 +41,28 @@ readonly UPDATE_TIMEOUT=180
 readonly INSTALL_TIMEOUT=300
 readonly ATTEMPTS=3
 
+# Elevation on the OUTSIDE, `timeout` on the inside. Review on #408 caught the
+# ordering and it is not cosmetic: with `timeout` outermost the SIGTERM goes to
+# the elevation helper, which may not forward it — leaving `apt-get` orphaned
+# while still holding the dpkg lock, so every subsequent retry fails on the lock
+# rather than on the original problem. A retry loop that guarantees its own
+# retries fail is worse than no retry loop at all.
+#
+# `DEBIAN_FRONTEND=noninteractive` for the same class of reason: a package that
+# prompts for configuration blocks on stdin that will never arrive in CI, burning
+# the whole timeout budget waiting for a human who is not there. Passed through
+# explicitly because the environment is scrubbed on elevation.
+#
+# Set via `env` rather than as a bare `VAR=value` argument to the elevation
+# helper. Both work on a standard GitHub runner (`ALL=(ALL) NOPASSWD:ALL`
+# implies the privilege), but the bare form additionally requires SETENV in
+# sudoers, so on a stricter host it fails outright — and it fails by refusing to
+# run at all, which would break the wrapper rather than degrade it. `env` is a
+# plain command and needs no such privilege. (Review on #409; both reviewers
+# raised it independently.)
 for attempt in $(seq 1 "$ATTEMPTS"); do
-    if timeout "$UPDATE_TIMEOUT" sudo apt-get update -qq &&
-        timeout "$INSTALL_TIMEOUT" sudo apt-get install -yq "$APT_PACKAGE"; then
+    if sudo env DEBIAN_FRONTEND=noninteractive timeout "$UPDATE_TIMEOUT" apt-get update -qq &&
+        sudo env DEBIAN_FRONTEND=noninteractive timeout "$INSTALL_TIMEOUT" apt-get install -yq "$APT_PACKAGE"; then
         echo "Installed ${APT_PACKAGE} on attempt ${attempt}."
         exit 0
     fi

crates/rustynes-frontend/src/app.rs

@@ -7275,6 +7275,11 @@ impl App {
         perf_view.render_work = r.work;
         perf_view.render_lock = r.lock;
         perf_view.render_cpu = r.cpu;
+        #[cfg(feature = "debug-hooks")]
+        {
+            perf_view.lock_gap_hits = r.lock_gap_hits;
+            perf_view.lock_gap_obs = r.lock_gap_obs;
+        }
         // F16 — how many frames the compositor composited but never scanned
         // out, cumulative. A rising count means THIS SURFACE IS NOT BEING SHOWN;
         // it is the signal that distinguishes that from "this compositor reports
@@ -9726,9 +9731,29 @@ impl ApplicationHandler<AppEvent> for App {
                     // scope mirrors the common `else` branch exactly; the only reason
                     // this branch later re-takes the lock is that the debugger pass
                     // needs a live `&mut Nes`, which the common branch does not.
+                    // v2.3.9 item B — the emulator's cumulative cycle for the frame
+                    // whose framebuffer this pass will copy.
+                    //
+                    // Read on ACQUIRING the lock, a few lines before the copy itself
+                    // rather than at it. Equivalent, and worth stating why rather
+                    // than leaving it to be re-derived: the emulator cannot advance
+                    // while this guard is held, so every reading taken anywhere
+                    // inside this scope names the same frame. The earlier wording
+                    // said "at the moment the framebuffer is copied", which was
+                    // close enough to be misleading — review on #409 asked, which
+                    // means the next reader would have too.
+                    //
+                    // Declared outside the scope so it outlives the guard and can be
+                    // compared at the egui pass; see `RenderPerf::record_lock_gap`.
+                    #[cfg(feature = "debug-hooks")]
+                    let cycle_at_fb: Option<u64>;
                     {
                         let mut guard = self.emu.lock_timed(&mut lock_wait);
                         let emu = &mut *guard;
+                        #[cfg(feature = "debug-hooks")]
+                        {
+                            cycle_at_fb = emu.nes.as_ref().map(rustynes_core::Nes::cycle);
+                        }
                         // Backfill the presented framebuffer into staging under the
                         // held lock (a ROM may or may not be loaded). The debugger
                         // panels read `nes` from the re-acquired lock below. v1.7.1
@@ -9942,6 +9967,22 @@ impl ApplicationHandler<AppEvent> for App {
                         // fold producer blocking into the UI phase, which is the
                         // same defect the F8 wait clock had.
                         let mut guard = self.emu.lock_timed(&mut lock_wait);
+                        // v2.3.9 item B — did the emulation thread take the lock
+                        // in the gap since the framebuffer copy? Recorded BEFORE
+                        // `run_shell_ui`, because that is the read whose
+                        // consistency with the presented frame is in question.
+                        // Both sides must be `Some` for the comparison to mean
+                        // anything: a redraw with no ROM loaded is not an
+                        // observation, and counting it would dilute the rate
+                        // toward zero — the denominator has to be redraws where
+                        // the race COULD have fired.
+                        #[cfg(feature = "debug-hooks")]
+                        if let (Some(before), Some(now)) = (
+                            cycle_at_fb,
+                            guard.nes.as_ref().map(rustynes_core::Nes::cycle),
+                        ) {
+                            self.render_perf.record_lock_gap(before != now);
+                        }
                         #[cfg(not(target_arch = "wasm32"))]
                         let t_ui = Instant::now();
                         let nes_for_render = guard.nes.as_mut();

crates/rustynes-frontend/src/debugger/perf_panel.rs

@@ -258,6 +258,44 @@ pub fn show(
                     stats_row(ui, "produce cost", &v.produce_cost, v.target_ms);
                 });
 
+            // v2.3.9 item B — the two-acquisition race, MEASURED.
+            //
+            // The `needs_nes` render arm takes the emulator lock twice per
+            // redraw: once for the framebuffer the user sees, again for the egui
+            // pass where panels read `&mut Nes`. If the emulation thread takes it
+            // in between, the screen shows one frame while a panel describes the
+            // next — which in Pixel Provenance would be a confidently wrong
+            // answer.
+            //
+            // Shown as a rate rather than a verdict. Zero over a long capture
+            // BOUNDS the race; it does not prove absence, and the label says so
+            // rather than letting a reader infer it.
+            #[cfg(feature = "debug-hooks")]
+            if v.lock_gap_obs > 0 {
+                ui.separator();
+                // Percentage of observations, computed in f64 so a long capture
+                // does not lose precision the way an f32 ratio would.
+                #[expect(
+                    clippy::cast_precision_loss,
+                    reason = "display-only ratio; u64 counts here are far below 2^53"
+                )]
+                let pct = (v.lock_gap_hits as f64) * 100.0 / (v.lock_gap_obs as f64);
+                ui.label(egui::RichText::new("panel/screen frame skew").strong());
+                ui.label(format!(
+                    "{} of {} redraws ({pct:.1}%)",
+                    v.lock_gap_hits, v.lock_gap_obs
+                ))
+                .on_hover_text(
+                    "Redraws where the emulator advanced between the framebuffer \
+                     copy and the panel read, so a debugger panel described a \
+                     LATER frame than the one on screen. Counted only while a \
+                     panel that needs `&mut Nes` is open and a ROM is loaded — \
+                     that is when the race can fire at all. A zero here bounds \
+                     the effect over this capture; it is not proof it cannot \
+                     happen.",
+                );
+            }
+
             // feature K — the live frame-time sparkline (presented = bright,
             // produced = faint, with the frame-deadline reference line).
             ui.separator();

crates/rustynes-frontend/src/perf.rs

@@ -220,6 +220,31 @@ pub struct RenderPerf {
     /// Subtracted out of `work` so that series finally means work alone:
     /// `work = total - wait - lock`.
     lock: SampleRing,
+    /// v2.3.9 item B — redraws where the emulator advanced BETWEEN the
+    /// framebuffer copy and the egui pass, and the total observed.
+    ///
+    /// The `needs_nes` render arm — taken exactly when a debugger or tool panel
+    /// is open — acquires the emulator lock TWICE per redraw: once to copy the
+    /// framebuffer the user will see, and again sixty lines later for
+    /// `run_shell_ui`, where panels read `&mut Nes`. The guard is dropped
+    /// between them so the composite work does not hold the emulator.
+    ///
+    /// If the emulation thread takes the lock in that gap, the screen shows
+    /// frame `N` while a panel describes `N+1` — which would be a confidently
+    /// wrong answer in Pixel Provenance, whose whole purpose is explaining the
+    /// pixel you are looking at.
+    ///
+    /// Counted rather than assumed. The plan recorded it as a hypothesis from
+    /// reading the lock structure, and this line has already retracted one
+    /// conclusion drawn from reading rather than measuring, so it is measured:
+    /// `hits` non-zero confirms the race fires, zero over a long capture with a
+    /// panel open bounds it.
+    #[cfg(feature = "debug-hooks")]
+    lock_gap_hits: u64,
+    /// Denominator for [`Self::lock_gap_hits`] — redraws where both
+    /// observations were taken (a ROM is loaded and the arm ran twice).
+    #[cfg(feature = "debug-hooks")]
+    lock_gap_obs: u64,
     /// 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
@@ -239,6 +264,13 @@ pub struct RenderPerf {
 /// theoretical risk.
 #[derive(Debug, Clone, Copy, Default)]
 pub struct RenderStats {
+    /// v2.3.9 item B — redraws where the emulator advanced between the
+    /// framebuffer copy and the egui pass. See `RenderPerf::record_lock_gap`.
+    #[cfg(feature = "debug-hooks")]
+    pub lock_gap_hits: u64,
+    /// Denominator for [`Self::lock_gap_hits`].
+    #[cfg(feature = "debug-hooks")]
+    pub lock_gap_obs: u64,
     /// egui shell build.
     pub ui: IntervalStats,
     /// GPU encode + submit + present.
@@ -314,6 +346,27 @@ impl RenderPerf {
             work: self.work.stats(),
             lock: self.lock.stats(),
             cpu: self.cpu.stats(),
+            #[cfg(feature = "debug-hooks")]
+            lock_gap_hits: self.lock_gap_hits,
+            #[cfg(feature = "debug-hooks")]
+            lock_gap_obs: self.lock_gap_obs,
+        }
+    }
+
+    /// v2.3.9 item B — record one redraw's two-acquisition observation.
+    ///
+    /// `advanced` is whether `Nes::cycle()` differed between the framebuffer
+    /// copy and the egui pass. The cycle counter is cumulative and monotonic,
+    /// and `produce_one_frame` holds the lock across a WHOLE frame, so any
+    /// change at all means at least one complete frame landed in the gap.
+    #[cfg(feature = "debug-hooks")]
+    pub const fn record_lock_gap(&mut self, advanced: bool) {
+        // Plain `+= 1`: one increment per redraw, so a `u64` cannot overflow in
+        // any run that ends. `saturating_add` here suggested a bound worth
+        // reasoning about and there is none. (Review nitpick on #409.)
+        self.lock_gap_obs += 1;
+        if advanced {
+            self.lock_gap_hits += 1;
         }
     }
 
@@ -331,6 +384,18 @@ impl RenderPerf {
         self.work.clear();
         self.lock.clear();
         self.cpu.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
+        // change mixes two populations into one percentage and reports it as a
+        // single measurement. Caught in review on #409 — the new counters had
+        // been added to `stats()` and not to `clear()`, which is precisely how
+        // `wait` went wrong before them.
+        #[cfg(feature = "debug-hooks")]
+        {
+            self.lock_gap_hits = 0;
+            self.lock_gap_obs = 0;
+        }
     }
 }
 
@@ -688,6 +753,15 @@ pub struct PerfView {
     /// v2.3.3 F15 — interval between display-tick sends, milliseconds. See
     /// `PerfStats::tick_iv`.
     pub tick_iv: IntervalStats,
+    /// v2.3.9 item B — redraws where the emulator advanced between the
+    /// framebuffer copy and the egui pass, and the total observed. See
+    /// `RenderPerf::record_lock_gap` (plain code span: the method is
+    /// `debug-hooks`-gated, so a default doc build cannot resolve a link).
+    #[cfg(feature = "debug-hooks")]
+    pub lock_gap_hits: u64,
+    /// Denominator for [`Self::lock_gap_hits`].
+    #[cfg(feature = "debug-hooks")]
+    pub lock_gap_obs: u64,
     /// 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`].
@@ -828,6 +902,54 @@ pub struct PerfView {
     pub recent_produced_ms: Vec<f32>,
 }
 
+#[cfg(all(test, feature = "debug-hooks"))]
+mod lock_gap_tests {
+    use super::RenderPerf;
+
+    /// The counter must distinguish "the race did not fire" from "nothing was
+    /// observed". Both read as zero hits, and only the denominator separates
+    /// them — which is the whole reason a rate is reported rather than a count.
+    #[test]
+    fn an_unobserved_redraw_is_not_a_clean_one() {
+        let p = RenderPerf::default();
+        let s = p.stats();
+        assert_eq!((s.lock_gap_hits, s.lock_gap_obs), (0, 0));
+    }
+
+    /// `clear()` must reset the counters with everything else. A rate is a
+    /// ratio over a population, and carrying the numerator and denominator
+    /// across a ROM or pacing-regime change mixes two populations into one
+    /// percentage and reports it as a single measurement. Caught in review on
+    /// #409, which is the same defect the `wait` series had before it.
+    #[test]
+    fn clear_resets_the_lock_gap_counters_too() {
+        let mut p = RenderPerf::default();
+        p.record_lock_gap(true);
+        p.record_lock_gap(false);
+        assert_eq!(p.stats().lock_gap_obs, 2, "premise: something was counted");
+
+        p.clear();
+
+        let s = p.stats();
+        assert_eq!(
+            (s.lock_gap_hits, s.lock_gap_obs),
+            (0, 0),
+            "a rate carried across a regime change is two populations in one number"
+        );
+    }
+
+    #[test]
+    fn hits_and_observations_are_counted_separately() {
+        let mut p = RenderPerf::default();
+        p.record_lock_gap(false);
+        p.record_lock_gap(true);
+        p.record_lock_gap(false);
+        let s = p.stats();
+        assert_eq!(s.lock_gap_obs, 3, "every observation counts");
+        assert_eq!(s.lock_gap_hits, 1, "only the advancing redraw is a hit");
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use super::*;

to-dos/plans/v2.3.9-crucible-plan.md

@@ -169,6 +169,19 @@ all-attempts-fail produces three warnings and exits 1; fail-fail-succeed produce
 two warnings, reports the attempt it succeeded on, and exits 0. The unset-package
 guard exits 1 rather than guessing. shellcheck clean.
 
+**Two ordering defects caught in review on #408**, both of which would have made
+the script worse than nothing on the exact path it exists to protect:
+
+- **Elevation must be outermost, `timeout` inside it.** With `timeout` on the
+  outside the signal goes to the elevation helper, which may not forward it —
+  leaving `apt-get` orphaned and still holding the dpkg lock, so every subsequent
+  retry fails on the lock rather than on the original problem. A retry loop that
+  guarantees its own retries fail is worse than no retry loop.
+- **`DEBIAN_FRONTEND=noninteractive`.** A package that prompts for configuration
+  blocks on stdin that will never arrive in CI, burning the whole timeout budget
+  waiting for a human who is not there — the same failure this script exists to
+  bound, arriving through a door it had left open.
+
 **Scope discipline:** deliberately not a general-purpose apt wrapper. One
 package, taken from a workflow `env:` and never from event data — which is the
 injection vector the Actions security guidance names — and a hard failure when