diff --git a/.github/scripts/apt-install-retry.sh b/.github/scripts/apt-install-retry.sh index a605640a..4ccc1504 100755 --- a/.github/scripts/apt-install-retry.sh +++ b/.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 diff --git a/crates/rustynes-frontend/src/app.rs b/crates/rustynes-frontend/src/app.rs index 3f01bedb..57d09566 100644 --- a/crates/rustynes-frontend/src/app.rs +++ b/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 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; { 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 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(); diff --git a/crates/rustynes-frontend/src/debugger/perf_panel.rs b/crates/rustynes-frontend/src/debugger/perf_panel.rs index 708bdfef..fc971ebd 100644 --- a/crates/rustynes-frontend/src/debugger/perf_panel.rs +++ b/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(); diff --git a/crates/rustynes-frontend/src/perf.rs b/crates/rustynes-frontend/src/perf.rs index 60ff9a7e..c70e4771 100644 --- a/crates/rustynes-frontend/src/perf.rs +++ b/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, } +#[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::*; diff --git a/to-dos/plans/v2.3.9-crucible-plan.md b/to-dos/plans/v2.3.9-crucible-plan.md index 8d03d1ed..6ea8698a 100644 --- a/to-dos/plans/v2.3.9-crucible-plan.md +++ b/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