diff --git a/CHANGELOG.md b/CHANGELOG.md index e4ae170..0b0e665 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,30 @@ All notable changes to RustyN64 are documented here. The format is based on ### Fixed +- **Audio chopped rather than played, because the frontend offered the device + `fps / 60` of what it consumes and silence for the rest.** With the core at + ~8.5 FPS that is 14.2% — measured, at the device: **0 of 469** callbacks were + fully fed. `EmuCore::produce_audio` stages exactly one emulated frame of audio + per emulated frame, and no buffering strategy manufactures the remainder. + + `emu_thread::AudioServo` now stretches each frame's audio over the wall-clock + time that frame actually took: feed-forward from the measured frame interval, + trimmed by ring occupancy, clamped to `[1.0, 12.0]`. The samples are the same + samples, spent over the whole frame instead of a sixtieth of it — so a slow + core sounds like a slow tape rather than a stutter. **14.2% -> 90.9% + delivered, 100.0% in steady state**, the shortfall being the startup ramp from + an empty ring. Frames per second and UI latency are both unchanged. + + Determinism is untouched: the stretch applies in the frontend resampler, which + ADR 0004 already designates as the non-deterministic host-timing stage. With no + ring attached the servo never runs and behavior is byte-identical. + + Two claims about this symptom were **refuted** while root-causing it, both of + which had been recorded as fact: the emulated AI was suspected of gapping (it + does not — 108/120 frames audible, 3 underruns), and the reported "~1 s on / + ~1 s off" period was attributed to the ring's 0.25 s capacity (the measured + period was ~95 ms, set by the pacer). See `docs/audio.md`. + - **`AI_STATUS.FULL` could latch and never clear, so a game polling it for a free audio DMA slot spun forever** (ledger R-16). An unprogrammed `AI_DACRATE` mapped to a zero sample rate, which made `tick()` return before diff --git a/crates/rustyn64-frontend/examples/audio_probe.rs b/crates/rustyn64-frontend/examples/audio_probe.rs new file mode 100644 index 0000000..609095b --- /dev/null +++ b/crates/rustyn64-frontend/examples/audio_probe.rs @@ -0,0 +1,225 @@ +//! **Where does the audio actually stop?** — evidence for the ~1 s on / ~1 s off +//! report, gathered at each boundary rather than reasoned about. +//! +//! `crates/rustyn64-frontend/src/audio.rs` currently *asserts* the cause in its +//! module header: the producer stages one emulated frame of audio per emulated +//! frame while the device consumes in wall-clock time, so supply is `fps / 60` +//! and everything else is downstream of throughput. That is a plausible +//! mechanism and it has never been measured. This probe measures it. +//! +//! It also tests a **competing hypothesis the header does not consider**: that +//! the *emulated* AI is itself gapping — the game's audio DMA starving inside +//! the machine — which would produce silence no host-side buffering could fix +//! and would be a genuine emulation defect rather than a speed consequence. +//! Those two have different signatures and this separates them: +//! +//! | | host starvation | emulated-AI gap | +//! | --- | --- | --- | +//! | frames carrying audible samples | **all of them** | only some | +//! | `Audio::underruns` | flat | climbing | +//! | silence period | set by the pacer (~`MAX_CATCHUP_FRAMES` / fps) | set by the game | +//! +//! The reported ~1 s period is the thing to explain, and neither hypothesis +//! predicts it on its face — 3 catch-up frames at ~15 FPS is a ~200 ms cycle, +//! not a 2 s one. Printing the actual run lengths is the point. +//! +//! ```text +//! RUSTYN64_PROBE_ROM=/path/rom.z64 \ +//! cargo run --release --example audio_probe --features fast-exec,fast-scheduler +//! ``` +//! +//! No audio device is opened and none is needed: every quantity here is on the +//! core side of `AudioRing::push`, which is exactly the half the header's claim +//! is about. + +use std::time::Instant; + +use rustyn64_frontend::emu::EmuCore; +use rustyn64_frontend::{FB_MAX_H, FB_MAX_W}; + +/// Frames to search for the VI coming up. Super Mario 64 takes 36. +const MAX_WARM: usize = 300; + +/// Timed frames. At ~15 FPS this is ~8 s of wall clock and ~5 s of emulated +/// audio — several periods of the reported ~1 s cycle, which a shorter window +/// could straddle without ever showing one. +const FRAMES: usize = 120; + +/// The host rate the resampler targets. Fixed rather than device-negotiated so +/// the run is reproducible without a sound card; 48 kHz is `EmuCore`'s default. +const OUTPUT_RATE: u32 = 48_000; + +/// Below this peak amplitude a frame is treated as silence. Not zero: the AI +/// decays the held sample toward zero on underrun rather than snapping to it, +/// so a strict `== 0.0` test would call a decaying tail "audible" and hide the +/// very gaps this probe exists to find. +const SILENCE_FLOOR: f32 = 1.0e-4; + +/// One emulated frame's audio, reduced to what distinguishes the hypotheses. +struct FrameAudio { + /// Interleaved stereo samples staged for the ring. + samples: usize, + /// Peak absolute amplitude in the frame. + peak: f32, + /// `Audio::underruns` after this frame. + underruns: u64, +} + +fn main() -> Result<(), Box> { + // The env var and the file read are HARNESS MISCONFIGURATION, not untrusted + // input: they say the operator did not set up the run. Those keep panicking, + // because a probe that cannot start must stop loudly. The ROM *contents* are + // parsed data and get a typed error, which is the distinction the rule draws. + let path = std::env::var("RUSTYN64_PROBE_ROM").unwrap_or_else(|_| { + panic!( + "set RUSTYN64_PROBE_ROM: the committed homebrew ROMs do not run a \ + game audio engine, so a run against one would measure silence and \ + prove nothing about the reported hiccup" + ) + }); + let raw = std::fs::read(&path).unwrap_or_else(|e| panic!("probe ROM unreadable: {path}: {e}")); + let mut core = EmuCore::new(0); + core.set_output_rate(OUTPUT_RATE); + core.load_rom(&raw) + .map_err(|e| format!("probe ROM did not parse or boot: {path}: {e:?}"))?; + + // Warm to a live VI, matching every other harness here: boot is not steady + // state, and audio during boot is not what was reported. + let mut buf = vec![0u8; (FB_MAX_W * FB_MAX_H * 4) as usize]; + let mut warm = 0usize; + loop { + core.run_frame(); + drop(core.drain_audio()); + warm += 1; + let (w, h) = core.system().bus.scanout_scaled(&mut buf); + if (w > 0 && h > 0) || warm >= MAX_WARM { + break; + } + } + + // Captured BEFORE the loop. Taking the baseline from the first timed frame + // instead would silently drop any underrun that frame recorded -- a reviewer + // caught the documented "3 underruns" being an off-by-one-frame figure. + let underruns_before = core.audio_underruns(); + let t0 = Instant::now(); + let mut log = Vec::with_capacity(FRAMES); + for _ in 0..FRAMES { + core.run_frame(); + let samples = core.drain_audio(); + let peak = samples.iter().fold(0.0f32, |m, s| m.max(s.abs())); + log.push(FrameAudio { + samples: samples.len(), + peak, + underruns: core.audio_underruns(), + }); + } + let wall = t0.elapsed().as_secs_f64(); + + report( + &path, + &log, + wall, + core.system().bus.audio.sample_rate(), + underruns_before, + ); + Ok(()) +} + +/// Print the evidence. Split from `main` so the measurement and its +/// presentation are separable, and because together they exceed the line gate. +#[allow( + clippy::cast_precision_loss, + reason = "sample counts over 120 frames are far below 2^53" +)] +fn report(path: &str, log: &[FrameAudio], wall: f64, in_rate: u32, underruns_before: u64) { + let total_samples: usize = log.iter().map(|f| f.samples).sum(); + let audible = log.iter().filter(|f| f.peak > SILENCE_FLOOR).count(); + let underruns = log.last().map_or(0, |f| f.underruns) - underruns_before; + + // Emulated audio produced, against wall-clock elapsed. THIS is the header's + // claim, stated as a ratio it can be checked against. + let produced_secs = (total_samples / 2) as f64 / f64::from(OUTPUT_RATE); + let supply = produced_secs / wall; + let fps = log.len() as f64 / wall; + + println!("rom={path}"); + println!( + "frames={} wall={wall:.3}s fps={fps:.2} AI rate={in_rate} Hz host rate={OUTPUT_RATE} Hz", + log.len() + ); + println!(); + println!("--- boundary 1: does the emulated AI produce continuous audio? ---"); + println!( + " frames carrying audible samples : {audible}/{} ({:.1}%)", + log.len(), + audible as f64 / log.len() as f64 * 100.0 + ); + println!(" AI underruns over the window : {underruns}"); + println!( + " samples staged per frame : {:.0} (expected {:.0} = rate/60)", + total_samples as f64 / log.len() as f64, + f64::from(OUTPUT_RATE) / 60.0 * 2.0 + ); + println!(); + println!("--- boundary 2: is supply enough for a real-time device? ---"); + println!(" emulated audio produced : {produced_secs:.3} s"); + println!(" wall clock elapsed : {wall:.3} s"); + println!( + " supply ratio : {:.1}% (fps/60 = {:.1}%)", + supply * 100.0, + fps / 60.0 * 100.0 + ); + println!(); + print_runs(log); +} + +/// Print the run-length timeline: the reported symptom is a *period*, and only +/// run lengths can confirm or refute a ~1 s one. +#[allow( + clippy::cast_precision_loss, + reason = "run lengths over 120 frames are far below 2^53" +)] +fn print_runs(log: &[FrameAudio]) { + println!("--- boundary 3: what is the actual period of the gaps? ---"); + let mut runs: Vec<(bool, usize)> = Vec::new(); + for f in log { + let loud = f.peak > SILENCE_FLOOR; + match runs.last_mut() { + Some((kind, n)) if *kind == loud => *n += 1, + _ => runs.push((loud, 1)), + } + } + if runs.len() == 1 { + println!( + " no alternation at all: {} frames, all {}", + log.len(), + if runs[0].0 { "audible" } else { "silent" } + ); + println!(" => the emulated stream does NOT gap; any chopping is host-side."); + return; + } + let silent: Vec = runs.iter().filter(|r| !r.0).map(|r| r.1).collect(); + let loud: Vec = runs.iter().filter(|r| r.0).map(|r| r.1).collect(); + let mean = |v: &[usize]| { + if v.is_empty() { + 0.0 + } else { + v.iter().sum::() as f64 / v.len() as f64 + } + }; + println!( + " runs: {} audible (mean {:.1} frames = {:.0} ms emulated), \ + {} silent (mean {:.1} frames = {:.0} ms emulated)", + loud.len(), + mean(&loud), + mean(&loud) * 1000.0 / 60.0, + silent.len(), + mean(&silent), + mean(&silent) * 1000.0 / 60.0, + ); + print!(" timeline: "); + for f in log { + print!("{}", if f.peak > SILENCE_FLOOR { '#' } else { '.' }); + } + println!(); +} diff --git a/crates/rustyn64-frontend/src/audio.rs b/crates/rustyn64-frontend/src/audio.rs index 8c61540..4872366 100644 --- a/crates/rustyn64-frontend/src/audio.rs +++ b/crates/rustyn64-frontend/src/audio.rs @@ -18,17 +18,42 @@ //! need `unsafe` or a new dependency and is still worth doing; this removes the //! deadline hazard without either. //! -//! **What this does not fix — and what the ~1 s on / ~1 s off chopping actually -//! is.** The producer stages one *emulated frame* of audio per emulated frame +//! **What this does not fix — and what the chopping actually is. MEASURED, and +//! the earlier revision of this paragraph asserted it instead.** The producer +//! stages one *emulated frame* of audio per emulated frame //! (`EmuCore::produce_audio`, private — hence a code span and not a link, which -//! `rustdoc -D warnings` rejects from public docs); the device consumes in wall-clock -//! time. So the supply ratio is exactly `fps / 60`, and at the ~10 FPS this core -//! currently sustains the ring receives under a fifth of what it must deliver. +//! `rustdoc -D warnings` rejects from public docs); the device consumes in +//! wall-clock time. So the supply ratio is exactly `fps / 60`. Two probes now +//! confirm that on Super Mario 64 rather than reasoning it (`docs/audio.md` +//! §*The chopping, measured at both boundaries*): +//! +//! - `examples/audio_probe.rs` — the emulated AI stream is **continuous** +//! (108/120 frames audible, 3 underruns), staging exactly `rate / 60` samples +//! per frame, and supply is **26.1%** against `fps / 60 = 26.1%`. +//! - `emu_thread`'s `measure_audio_gaps_at_the_device_boundary` — at the device, +//! **0 of 469** callbacks were fully fed and **14.2%** of samples arrived. +//! //! That is **starvation by throughput**, not a ring defect and not a resampler -//! defect: no buffering strategy manufactures the missing 80%. It closes when the -//! core gets faster and not before — see `docs/performance.md`, which also records -//! that 60 FPS is out of reach for this execution model, so some form of explicit -//! slow-running audio policy will eventually be needed instead. +//! defect: no buffering strategy manufactures the missing 74%. +//! +//! **The reported "~1 s on / ~1 s off" does not reproduce, and this paragraph +//! used to repeat it as fact.** The measured silent runs are **95 ms mean, +//! 128 ms max** — a ~10 Hz chop, an order of magnitude off the report. The +//! period is set by the pacer (one frame plus its yield), not by this ring's +//! 0.25 s capacity, so "the ~1 s period is the ring's capacity" was wrong twice +//! over. +//! +//! The underlying shortfall closes only when the core gets faster — see +//! `docs/performance.md`, which records that 60 FPS is out of reach for this +//! execution model. What the frontend can choose is *which* failure a listener +//! hears, and it now chooses continuity over pitch. +//! +//! **The servo described above now exists** — `emu_thread::AudioServo`, which +//! reads [`AudioRing::occupancy`] as its trim term. It does not create the +//! missing samples (nothing can); it spends the ones there are over the whole +//! wall-clock frame, trading pitch for continuity. Measured **14.2% -> 90.9%** +//! delivered and **100% in steady state**, with the shortfall confined to the +//! ~4 s ramp from an empty ring at startup. use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Arc, Mutex}; diff --git a/crates/rustyn64-frontend/src/emu.rs b/crates/rustyn64-frontend/src/emu.rs index 140d341..0438604 100644 --- a/crates/rustyn64-frontend/src/emu.rs +++ b/crates/rustyn64-frontend/src/emu.rs @@ -37,6 +37,16 @@ const MASTER_TICKS_PER_FRAME: u64 = rustyn64_core::MASTER_HZ / 60; /// The default host output rate (Hz) before a `cpal` device reports its own. const DEFAULT_OUTPUT_RATE: u32 = 48_000; +/// The furthest one emulated frame's audio may be stretched over host time. +/// +/// A bound, not a tuning knob. It answers "how slow may the core get before the +/// frontend stops trying to hide it", and **12.0 means 5 FPS** — below that the +/// audio chops again rather than degenerating into an unrecognizable drone that +/// also pins the ring. The measured floor this has to clear is the default +/// build's ~8.5 FPS, which needs 7.06 (`docs/audio.md`), so the bound is chosen +/// to sit clear of the worst case actually observed rather than at it. +pub const MAX_AUDIO_STRETCH: f64 = 12.0; + /// A produced video frame: an RGBA8 buffer plus its active dimensions. /// /// The N64 VI resolution is variable; `w`/`h` give the active sub-rectangle the @@ -81,6 +91,17 @@ pub struct EmuCore { /// rate conversion stays continuous (click-free) across frames. Frontend-only /// state — the deterministic core never sees it (ADR 0004). resample_pos: f64, + /// How far to stretch one emulated frame's audio over host time, set by the + /// pacer's servo. `1.0` is real time. + /// + /// The core produces exactly one emulated frame of audio per emulated frame, + /// so when it runs at `fps` the device is offered `fps / 60` of what it + /// consumes and the rest is silence (`docs/audio.md`). Stretching by + /// `60 / fps` makes the stream continuous at the cost of pitch — the + /// slow-tape sound — which is the policy this frontend ships. Frontend-only, + /// like `resample_pos`: it is a function of host wall-clock and must never + /// reach the core. + audio_stretch: f64, /// Produced-frame counter, surfaced via `frame_count` for the status bar. frames: u64, /// `true` while paused (the pacer keeps running, the core does not advance). @@ -99,6 +120,7 @@ impl EmuCore { audio: Vec::new(), output_rate: DEFAULT_OUTPUT_RATE, resample_pos: 0.0, + audio_stretch: 1.0, frames: 0, paused: false, loaded: false, @@ -141,6 +163,27 @@ impl EmuCore { } } + /// Set how far one emulated frame's audio is stretched over host time. + /// + /// `1.0` is real time and is the default, so a caller that never touches + /// this gets exactly the previous behavior. The pacer's servo drives it + /// (`emu_thread::AudioServo`); it is host-timing state and never reaches the + /// core (ADR 0004). + /// + /// Out-of-range and non-finite values are clamped where they are used + /// (`stretched_rate`) rather than rejected here, so a servo that + /// misbehaves degrades to a bounded pitch shift instead of a panic on the + /// audio path. + pub const fn set_audio_stretch(&mut self, stretch: f64) { + self.audio_stretch = stretch; + } + + /// The current audio stretch factor. + #[must_use] + pub const fn audio_stretch(&self) -> f64 { + self.audio_stretch + } + /// Observed AI buffer underruns (starvations) — surfaced so the frontend / /// harness can see them rather than the resampler silently concealing them. #[must_use] @@ -432,22 +475,56 @@ impl EmuCore { self.audio.clear(); let in_rate = self.system.bus.audio.sample_rate(); let samples = self.system.bus.drain_audio_samples(); + // The rate the resampler targets: the device rate stretched by however + // much slower than real time the core is running. At `stretch == 1.0` + // this is exactly `output_rate` and the arithmetic below is a no-op, so + // a build with no servo attached is unchanged. + let effective = stretched_rate(self.output_rate, self.audio_stretch); if in_rate == 0 || samples.is_empty() { - // Idle: one frame of silence at the host rate (keeps the ring fed). - let pairs = (self.output_rate / 60) as usize; + // Idle: one frame of silence at the stretched rate (keeps the ring + // fed). This has to stretch too — a silent frame that stayed 1/60 s + // long would leave exactly the gap the stretch exists to close. + let pairs = (effective / 60) as usize; self.audio.resize(pairs * 2, 0.0); return; } resample_stereo( &samples, in_rate, - self.output_rate, + effective, &mut self.resample_pos, &mut self.audio, ); } } +/// The device rate scaled by `stretch`, saturating rather than wrapping. +/// +/// Split out and pure so the saturation is testable without running a frame. The +/// clamp matters: `stretch` arrives from a servo reading host wall-clock, and an +/// `as`-cast of a `f64` that has gone non-finite or enormous would produce a +/// nonsense rate silently. `MIN` keeps the divisor positive so +/// `resample_stereo`'s `debug_assert` cannot trip and the idle path cannot +/// produce a zero-length frame. +fn stretched_rate(output_rate: u32, stretch: f64) -> u32 { + /// Never resample to under a quarter of the device rate: past that the + /// output is too sparse to interpolate meaningfully, and the case does not + /// arise from a slow core anyway (which only ever stretches upward). + const MIN: f64 = 0.25; + let s = if stretch.is_finite() { + stretch.clamp(MIN, MAX_AUDIO_STRETCH) + } else { + 1.0 + }; + #[allow( + clippy::cast_possible_truncation, + clippy::cast_sign_loss, + reason = "clamped to [output_rate/4, output_rate*MAX_AUDIO_STRETCH], well inside u32" + )] + let scaled = (f64::from(output_rate) * s) as u32; + scaled.max(1) +} + /// The geometry to present from a scan-out `(w, h)`: `Some((w, h))` when it is a /// non-empty frame that fits the blit's `FB_MAX` texture, or `None` (present a /// black default frame) for the blank `(0, 0)` case or a geometry that would @@ -514,6 +591,59 @@ mod tests { assert_eq!(emu.frame_count(), 1); } + /// **The stretch changes how many samples a frame stages** — the effect, + /// not just the setter. A `set_audio_stretch` that stored the value and was + /// never read would satisfy an assertion on `audio_stretch()` alone. + #[test] + fn a_stretched_frame_stages_proportionally_more_samples() { + let count = |stretch: f64| { + let mut emu = EmuCore::new(0); + emu.loaded = true; + emu.set_output_rate(48_000); + emu.set_audio_stretch(stretch); + emu.run_frame(); + emu.drain_audio().len() + }; + let real_time = count(1.0); + let quadruple = count(4.0); + assert!(real_time > 0, "a frame must stage some audio"); + // The idle path resizes to `effective / 60 * 2`, so the ratio is exact + // up to the integer division. + let ratio = quadruple as f64 / real_time as f64; + assert!( + (ratio - 4.0).abs() < 0.01, + "a 4x stretch must stage ~4x the samples; got {real_time} -> {quadruple} ({ratio:.3}x)" + ); + } + + /// The clamp is what stops a servo reading a wall clock from turning a + /// glitch into a nonsense rate; `as`-casting a non-finite `f64` is UB-adjacent + /// nonsense that would surface as silence or a panic deep in the resampler. + #[test] + fn stretched_rate_saturates_rather_than_trusting_the_servo() { + assert_eq!(stretched_rate(48_000, 1.0), 48_000); + assert_eq!(stretched_rate(48_000, 4.0), 192_000); + assert_eq!( + stretched_rate(48_000, 1.0e9), + (48_000.0 * MAX_AUDIO_STRETCH) as u32, + "an absurd stretch clamps to the documented maximum" + ); + assert_eq!( + stretched_rate(48_000, f64::NAN), + 48_000, + "a non-finite stretch falls back to real time" + ); + assert_eq!( + stretched_rate(48_000, f64::INFINITY), + 48_000, + "infinity is not finite, so it falls back too" + ); + assert!( + stretched_rate(48_000, -5.0) > 0, + "a negative stretch must still yield a usable rate" + ); + } + #[test] fn paused_does_not_advance() { let mut emu = EmuCore::new(0); diff --git a/crates/rustyn64-frontend/src/emu_thread.rs b/crates/rustyn64-frontend/src/emu_thread.rs index f104b03..8c95b43 100644 --- a/crates/rustyn64-frontend/src/emu_thread.rs +++ b/crates/rustyn64-frontend/src/emu_thread.rs @@ -10,8 +10,13 @@ //! Rate control, save-states, rewind, and run-ahead orchestration belong HERE //! (frontend-side), never in the core — the determinism contract. The loop is a //! wall-clock pacer driving a [`SaveStateCoordinator`] (rewind capture + -//! run-ahead + save/load), which is a plain `run_frame` when both are off. The -//! resampler servo is still a roadmap refinement. +//! run-ahead + save/load), which is a plain `run_frame` when both are off. +//! +//! **The resampler servo is implemented** (`AudioServo`, private): it stretches each +//! emulated frame's audio over the wall-clock time that frame actually took, so +//! a core slower than real time produces a continuous stream instead of +//! `fps / 60` of one. Measured 14.2% -> 90.9% delivered, 100% in steady state +//! (`docs/audio.md`). //! //! # The pacer, and the bug it replaces //! @@ -37,7 +42,7 @@ use web_time::{Duration, Instant}; use crate::audio::AudioRing; use crate::config::Region; -use crate::emu::EmuCore; +use crate::emu::{EmuCore, MAX_AUDIO_STRETCH}; use crate::input::SharedInput; use crate::present_buffer::PresentBuffer; use crate::savestate::{RewindConfig, RunAhead, SaveStateControls, SaveStateCoordinator}; @@ -69,6 +74,88 @@ const SLEEP_CHUNK: Duration = Duration::from_millis(2); /// which is exactly the bug this pacer replaces. const MAX_CATCHUP_FRAMES: u32 = 3; +/// The audio rate-control servo: how far to stretch one emulated frame's audio +/// so the device hears a continuous stream from a core slower than real time. +/// +/// **The problem it solves** (`docs/audio.md`): the core stages exactly one +/// emulated frame of audio per emulated frame, and the device consumes in +/// wall-clock time, so supply is `fps / 60` — measured at **14.2%** on the +/// default build. No buffering manufactures the rest. Stretching the resample by +/// `60 / fps` fills the gap with real samples instead of silence, at the cost of +/// pitch: the slow-tape sound. That is the shipped policy, chosen deliberately +/// over chopping and over muting. +/// +/// **Feed-forward plus a trim, not a pure integrator.** The dominant term is +/// measured directly — the wall-clock interval between produced frames — so the +/// servo is correct on its first frame instead of converging over seconds, which +/// a pure occupancy integrator with a 7x range to cover would not be. The +/// occupancy term only removes residual drift, because the feed-forward term +/// cannot know about samples already banked in the ring. +/// +/// Pure and separately testable, like [`Schedule`] above and for the same +/// reason: the decisions are checkable with synthetic inputs, no thread, no real +/// clock, no timing flake. +#[derive(Debug)] +struct AudioServo { + /// Smoothed wall-clock interval between produced frames. + interval: Option, +} + +impl AudioServo { + /// Weight of a new sample in the interval EMA. Low enough that one slow + /// frame does not swing the pitch audibly, high enough to track a real + /// change in load within a few frames. + const SMOOTHING: u32 = 8; + + /// How hard the ring's fill level trims the feed-forward term. + /// + /// **Measured, and deliberately the smallest of the three tried.** 0.2, 0.4 + /// and 0.6 all reach **100.0% steady-state delivery** and all reach their + /// first fully-fed callback at the same place (#15, ~320 ms); the only + /// difference is in the whole-window figure (90.6 / 91.3 / 91.9%), which is + /// dominated by the startup ramp from an empty ring and is not a + /// steady-state result. Picking 0.6 for that 1.3-point edge would be tuning + /// against a transient, so the lowest gain wins on the tiebreak that matters + /// here: a larger gain makes the pitch hunt audibly, and nothing was bought + /// with it. Re-run `measure_audio_gaps_at_the_device_boundary` before + /// changing it. + const TRIM_GAIN: f64 = 0.2; + + const fn new() -> Self { + Self { interval: None } + } + + /// Fold one measured frame interval into the estimate. + fn observe(&mut self, frame: Duration) { + self.interval = Some(self.interval.map_or(frame, |prev| { + (prev * (Self::SMOOTHING - 1) + frame) / Self::SMOOTHING + })); + } + + /// The stretch factor for the next frame. + /// + /// `fill` is the ring's occupancy as a fraction of capacity. Returns `1.0` + /// (real time, i.e. the previous behavior) until an interval has been + /// observed, and never *compresses* below real time: a core running faster + /// than 60 FPS is already supplying more than the device wants, and the + /// ring's drop-oldest is the right answer there. + fn stretch(&self, period: Duration, fill: f64) -> f64 { + let Some(interval) = self.interval else { + return 1.0; + }; + let period = period.as_secs_f64(); + if period <= 0.0 { + return 1.0; + } + // Feed-forward: one emulated frame must cover one wall-clock interval. + let base = interval.as_secs_f64() / period; + // Trim toward a half-full ring. Under half, stretch a little more; + // over half, a little less. + let trim = Self::TRIM_GAIN.mul_add(0.5 - fill.clamp(0.0, 1.0), 1.0); + (base * trim).clamp(1.0, MAX_AUDIO_STRETCH) + } +} + /// Wall-clock pacing diagnostics. /// /// Published for the UI and for the later perf work. Counters only — nothing @@ -82,6 +169,30 @@ pub struct PacerStats { pub snap_forwards: AtomicU64, /// Frames the pacer has produced. pub produced: AtomicU64, + /// The most recent audio stretch factor, as `f64::to_bits`, or **zero when + /// the servo has never run** — which is the case whenever no ring is + /// attached. + /// + /// Zero is a usable sentinel because `AudioServo::stretch` is clamped to + /// `[1.0, MAX_AUDIO_STRETCH]` and so can never produce it. That distinction + /// is the point: it lets a test tell "the servo ran and asked for real time" + /// apart from "the servo was never consulted", which are otherwise identical + /// from outside — the failure mode where rate control is computed correctly + /// and then never applied. + /// + /// A diagnostic. Nothing schedules against it (ADR 0006). + pub audio_stretch_bits: AtomicU64, +} + +impl PacerStats { + /// The last stretch the servo asked for, or `None` if it never ran. + #[must_use] + pub fn audio_stretch(&self) -> Option { + match self.audio_stretch_bits.load(Ordering::Relaxed) { + 0 => None, + bits => Some(f64::from_bits(bits)), + } + } } /// Everything [`EmuThread::spawn`] needs. @@ -232,6 +343,11 @@ impl EmuThread { // ADR 0004); with rewind off and run-ahead 0 the coordinator is a // plain `run_frame` + drain, so output stays byte-identical. let mut coordinator = SaveStateCoordinator::new(rewind, run_ahead, controls); + // Audio rate control. Only meaningful with a ring attached; with + // `ring: None` the servo is never consulted and the core keeps + // its default 1.0 stretch, so a headless build is unchanged. + let mut servo = AudioServo::new(); + let mut last_frame = Instant::now(); while run_flag.load(Ordering::Relaxed) { let due = schedule.frames_due(Instant::now()); let mut produced = 0u32; @@ -242,10 +358,33 @@ impl EmuThread { // UI stall. Per-frame gives the UI a window between each. while produced < due && run_flag.load(Ordering::Relaxed) { let ports = input.load_all(); + // Measured BEFORE the frame runs, from the last frame's + // completion: the servo needs the interval the device + // actually experienced, and the frame about to run has + // not happened yet. + let stretch = ring.as_ref().map(|r| { + let now = Instant::now(); + servo.observe(now - last_frame); + last_frame = now; + #[allow( + clippy::cast_precision_loss, + reason = "ring occupancy and capacity are far below 2^53" + )] + let fill = r.occupancy() as f64 / r.capacity().max(1) as f64; + servo.stretch(period, fill) + }); + if let Some(stretch) = stretch { + thread_stats + .audio_stretch_bits + .store(stretch.to_bits(), Ordering::Relaxed); + } let audio = emu.lock().map_or_else( |_| Vec::new(), |mut core| { core.set_controllers(ports); + if let Some(stretch) = stretch { + core.set_audio_stretch(stretch); + } let audio = coordinator.step(&mut core); // Published under the lock we already hold (as // RustyNES's emu thread does): one memcpy instead of @@ -404,6 +543,393 @@ mod tests { ); } + /// Before any frame has been timed the servo asks for real time, so a build + /// that never observes an interval is byte-identical to the pre-servo one. + #[test] + fn the_servo_asks_for_real_time_until_it_has_measured_something() { + let servo = AudioServo::new(); + let s = servo.stretch(Duration::from_secs_f64(1.0 / 60.0), 0.0); + assert!( + (s - 1.0).abs() < f64::EPSILON, + "an unmeasured servo must not change the rate; got {s}" + ); + } + + /// The feed-forward term IS the ratio of wall-clock interval to frame + /// period: a core running at a quarter speed must stretch four-fold, or the + /// device gets three-quarters silence. + #[test] + fn the_servo_stretches_by_exactly_how_far_behind_real_time_the_core_is() { + let period = Duration::from_secs_f64(1.0 / 60.0); + let mut servo = AudioServo::new(); + // A quarter speed: each emulated frame takes four frame periods. + servo.observe(period * 4); + // Half-full ring, so the trim term is exactly 1 and only the + // feed-forward term is under test. + let s = servo.stretch(period, 0.5); + assert!( + (s - 4.0).abs() < 1e-9, + "a quarter-speed core needs a 4x stretch; got {s}" + ); + } + + /// The trim pushes toward a half-full ring in both directions, and it is a + /// *trim*: it must not swamp the feed-forward term. + #[test] + fn the_trim_pushes_toward_half_full_without_swamping_the_feed_forward() { + let period = Duration::from_secs_f64(1.0 / 60.0); + let mut servo = AudioServo::new(); + servo.observe(period * 4); + let empty = servo.stretch(period, 0.0); + let half = servo.stretch(period, 0.5); + let full = servo.stretch(period, 1.0); + assert!( + empty > half && half > full, + "an emptier ring must ask for more stretch: {empty} / {half} / {full}" + ); + // Within 10% of the feed-forward term at either extreme (TRIM_GAIN/2). + assert!( + (empty - 4.0).abs() < 0.5 && (full - 4.0).abs() < 0.5, + "the trim must not dominate: {empty} / {full}" + ); + } + + /// A core running FASTER than real time must not compress: it is already + /// supplying more than the device consumes, and the ring's drop-oldest is + /// the right answer. Compressing would raise the pitch of a fast core. + #[test] + fn a_core_faster_than_real_time_is_never_compressed() { + let period = Duration::from_secs_f64(1.0 / 60.0); + let mut servo = AudioServo::new(); + servo.observe(period / 4); + assert!( + servo.stretch(period, 0.0) >= 1.0 && servo.stretch(period, 1.0) >= 1.0, + "stretch must never drop below real time" + ); + } + + /// The bound holds even for a core that has effectively stopped, so one + /// pathological stall cannot ask for a minutes-long stretch. + #[test] + fn a_stalled_core_is_clamped_to_the_documented_maximum() { + let period = Duration::from_secs_f64(1.0 / 60.0); + let mut servo = AudioServo::new(); + servo.observe(Duration::from_secs(30)); + let s = servo.stretch(period, 0.0); + assert!( + (s - MAX_AUDIO_STRETCH).abs() < f64::EPSILON, + "expected the clamp at {MAX_AUDIO_STRETCH}; got {s}" + ); + } + + /// **The servo is actually applied to the core, not merely computed.** + /// + /// Rate control that is calculated correctly and then dropped on the floor + /// passes every unit test above — this repo's decoded-but-no-op failure + /// mode, which has cost it real time before. + /// + /// Asserting the applied *value* is not enough on its own: a ROM-less core + /// runs far faster than real time, so the servo legitimately asks for `1.0`, + /// which is also the default. **So the destination is seeded with a value + /// the servo can never produce** (`SENTINEL`, outside the clamp range) and + /// the test asserts it was overwritten — the "seed the destination so it + /// differs from the expected result" rule, applied to a field whose + /// legitimate value is indistinguishable from its default. + /// + /// Mutation checks, both verified: + /// - delete `core.set_audio_stretch(stretch)` → the sentinel survives → red; + /// - delete the `ring.as_ref().map(...)` block → `audio_stretch()` stays + /// `None` → red. + #[test] + fn the_servo_is_applied_to_the_core_when_a_ring_is_attached() { + /// Outside `[1.0, MAX_AUDIO_STRETCH]`, so no servo output can equal it. + const SENTINEL: f64 = 99.0; + + let run = |ring: Option>| { + let mut core = EmuCore::new(0); + core.set_audio_stretch(SENTINEL); + let emu = Arc::new(Mutex::new(core)); + let thread = EmuThread::spawn(EmuThreadParams { + emu: Arc::clone(&emu), + input: Arc::new(SharedInput::new()), + present: PresentBuffer::new(), + ring, + region: Region::default(), + rewind: RewindConfig::default(), + run_ahead: RunAhead::default(), + controls: Arc::new(SaveStateControls::default()), + }); + // Long enough for several frame periods at 60 Hz. + std::thread::sleep(Duration::from_millis(200)); + let reported = thread.stats().audio_stretch(); + drop(thread); + let applied = emu.lock().expect("emu mutex").audio_stretch(); + (reported, applied) + }; + + let (reported, applied) = run(Some(Arc::new(AudioRing::new(4096)))); + let reported = reported.expect("the servo must run when a ring is attached"); + assert!( + (1.0..=MAX_AUDIO_STRETCH).contains(&reported), + "the servo's output must be in range; got {reported}" + ); + assert!( + (applied - SENTINEL).abs() > f64::EPSILON, + "the servo ran but its value never reached the core: the sentinel survived" + ); + assert!( + (applied - reported).abs() < f64::EPSILON, + "the core must hold what the servo last asked for: {applied} vs {reported}" + ); + + let (reported, applied) = run(None); + assert_eq!( + reported, None, + "with no ring there is nothing to rate-control, so the servo must not run" + ); + assert!( + (applied - SENTINEL).abs() < f64::EPSILON, + "with no ring the core's stretch must be left exactly as the caller set it" + ); + } + + /// **What the audio device actually experiences** — the host half of the + /// ~1 s on / ~1 s off report, measured rather than reasoned about. + /// + /// `examples/audio_probe.rs` measures the *core* half and settles it: the + /// emulated AI produces a continuous stream, and supply is exactly + /// `fps / 60`. Neither of those is what a listener hears. This spawns the + /// real [`EmuThread`] against a real [`AudioRing`] and drains it from a + /// wall-clock-paced consumer standing in for the `cpal` callback, so the + /// **period** of the gaps is observed at the point the symptom is reported. + /// + /// No audio device is opened. That is deliberate: a real device would add + /// its own scheduling to the thing being measured, and the quantity of + /// interest — how much of each buffer is real samples — is entirely + /// determined by [`AudioRing::pull`]. + /// + /// Needs a ROM with a running audio engine; skips loudly without one. + /// + /// ```text + /// RUSTYN64_PROBE_ROM=/path/rom.z64 cargo test -p rustyn64-frontend --release \ + /// --lib measure_audio_gaps -- --ignored --nocapture + /// ``` + #[test] + #[ignore = "a measurement, not a gate; ~10 s and needs a commercial ROM"] + fn measure_audio_gaps_at_the_device_boundary() { + /// Stereo samples per simulated device callback: 1024 frames, giving a + /// ~21 ms cadence. + /// + /// **A representative size, not a `cpal` default.** + /// `cpal::BufferSize::Default` defers to the host and device, so there is + /// no single figure to call the default — an earlier revision of this + /// comment claimed there was. What matters for this measurement is that + /// the cadence is in the right order of magnitude; the delivered-sample + /// percentage is a ratio and does not depend on it. + const BUF: usize = 2048; + /// Host rate the ring and consumer agree on. + const RATE: u32 = 48_000; + /// Wall-clock seconds to observe. Must span several of the reported + /// ~1 s cycles, or a run could straddle one and show nothing. + const OBSERVE: Duration = Duration::from_secs(10); + /// Below this a sample counts as silence. Matches `audio_probe.rs`'s + /// `SILENCE_FLOOR`, and exists because real audio contains exact zeros. + const FLOOR: f32 = 1.0e-4; + + let Ok(path) = std::env::var("RUSTYN64_PROBE_ROM") else { + println!("SKIP: set RUSTYN64_PROBE_ROM to a ROM that runs an audio engine"); + return; + }; + let raw = std::fs::read(&path).expect("probe ROM readable"); + let mut core = EmuCore::new(0); + core.set_output_rate(RATE); + core.load_rom(&raw).expect("probe ROM boots"); + // Warm past boot: the first frames are silent while the game starts its + // audio engine, and counting those would report a gap that is not the + // reported one. + for _ in 0..48 { + core.run_frame(); + drop(core.drain_audio()); + } + + // Same capacity the shipped `AudioOutput::open` uses: 0.25 s of stereo. + let ring = Arc::new(AudioRing::new(RATE as usize * 2 / 4)); + let emu = Arc::new(Mutex::new(core)); + + // A stand-in for the UI thread's OCCASIONAL emu-mutex takers (load ROM, + // save state, pause — `app.rs`; the per-frame present path uses the + // handoff and never takes this lock). The pacer's post-snap yield exists + // to keep these from starving, so any change to it has to be judged + // against this latency and not against throughput alone. + let ui_emu = Arc::clone(&emu); + let ui_stop = Arc::new(AtomicBool::new(false)); + let ui_flag = Arc::clone(&ui_stop); + let ui = std::thread::spawn(move || { + let mut waits = Vec::new(); + while !ui_flag.load(Ordering::Relaxed) { + let t = Instant::now(); + drop(ui_emu.lock().map(|c| c.frame_count())); + waits.push(t.elapsed()); + std::thread::sleep(Duration::from_millis(16)); + } + waits + }); + + let thread = EmuThread::spawn(EmuThreadParams { + emu: Arc::clone(&emu), + input: Arc::new(SharedInput::new()), + present: PresentBuffer::new(), + ring: Some(Arc::clone(&ring)), + region: Region::default(), + rewind: RewindConfig::default(), + run_ahead: RunAhead::default(), + controls: Arc::new(SaveStateControls::default()), + }); + + let period = Duration::from_secs_f64(BUF as f64 / 2.0 / f64::from(RATE)); + let mut buf = vec![0.0f32; BUF]; + let mut fed = Vec::new(); + let start = Instant::now(); + let mut next = start; + while start.elapsed() < OBSERVE { + next += period; + while Instant::now() < next { + std::thread::sleep(Duration::from_micros(200)); + } + ring.pull(&mut buf); + // How much of this buffer was real audio. `pull` zero-fills the + // tail on underrun, so trailing silence IS the underrun — but a + // genuinely quiet passage also reads as zero, which is why the core + // probe establishes separately that the stream is not silent. + // + // Thresholded rather than `!= 0.0`: real audio crosses zero, and an + // exact-zero test misreads a waveform crossing at the buffer tail as + // underrun. It biases DOWNWARD, so it understated both legs of the + // before/after equally and the comparison held — but the absolute + // percentages were pessimistic. + let real = buf + .iter() + .rposition(|s| s.abs() > FLOOR) + .map_or(0, |i| i + 1); + fed.push(real); + } + let stats = thread.stats(); + let (produced, bursts, snaps) = ( + stats.produced.load(Ordering::Relaxed), + stats.catchup_bursts.load(Ordering::Relaxed), + stats.snap_forwards.load(Ordering::Relaxed), + ); + drop(thread); + ui_stop.store(true, Ordering::Relaxed); + let mut waits = ui.join().expect("UI stand-in thread finishes"); + waits.sort_unstable(); + + let callbacks = fed.len(); + report_audio_gaps( + &fed, + BUF, + period, + &waits, + (produced, bursts, snaps), + OBSERVE, + ); + + assert!( + callbacks > 100, + "the consumer must actually have run; got {callbacks} callbacks" + ); + } + + /// Print what the device saw. Split from the measurement so the two are + /// separable — and because together they exceed the line gate. + #[allow( + clippy::cast_precision_loss, + reason = "callback counts over a 10 s window are far below 2^53" + )] + fn report_audio_gaps( + fed: &[usize], + buf: usize, + period: Duration, + waits: &[Duration], + pacer: (u64, u64, u64), + observe: Duration, + ) { + let callbacks = fed.len(); + let starved = fed.iter().filter(|n| **n < buf).count(); + let empty = fed.iter().filter(|n| **n == 0).count(); + let delivered: usize = fed.iter().sum(); + let wanted = callbacks * buf; + // Run lengths of fully-empty callbacks: the "off" half of the report. + let mut gaps = Vec::new(); + let mut run = 0usize; + for n in fed { + if *n == 0 { + run += 1; + } else if run > 0 { + gaps.push(run); + run = 0; + } + } + if run > 0 { + gaps.push(run); + } + let ms = |n: usize| n as f64 * period.as_secs_f64() * 1000.0; + let (produced, bursts, snaps) = pacer; + + println!("--- {callbacks} device callbacks of {buf} samples over {observe:?} ---"); + println!( + " callbacks fully fed : {}/{callbacks}", + callbacks - starved + ); + println!(" callbacks fully empty : {empty}/{callbacks}"); + println!( + " samples delivered : {delivered}/{wanted} ({:.1}%)", + delivered as f64 / wanted as f64 * 100.0 + ); + // The second half separately: with a servo attached the first seconds + // are its ramp (an empty ring being banked), and a whole-window figure + // charges that startup transient to steady-state quality. + let half = callbacks / 2; + let tail: usize = fed[half..].iter().sum(); + println!( + " ...second half only : {:.1}% (steady state; the first half includes any servo ramp)", + tail as f64 / ((callbacks - half) * buf) as f64 * 100.0 + ); + println!( + " first fully-fed call : {}", + fed.iter().position(|n| *n == buf).map_or_else( + || "never".to_string(), + |i| format!("#{i} ({:.0} ms in)", ms(i)) + ) + ); + println!( + " silent runs : {}, mean {:.1} ms, max {:.1} ms", + gaps.len(), + ms(gaps.iter().sum::()) / gaps.len().max(1) as f64, + ms(gaps.iter().copied().max().unwrap_or(0)), + ); + println!(" pacer: {produced} frames, {bursts} bursts, {snaps} snap-forwards"); + println!( + " UI emu-lock wait : p50 {:.3?} p99 {:.3?} max {:.3?} (n={})", + waits[waits.len() / 2], + waits[waits.len() * 99 / 100], + waits[waits.len() - 1], + waits.len() + ); + print!(" timeline: "); + for n in fed { + print!( + "{}", + match *n { + 0 => '.', + x if x == buf => '#', + _ => '+', + } + ); + } + println!(); + } + /// **End-to-end: the producer actually publishes into the handoff.** The /// `emu-thread` feature shipped without this wiring, so the UI had nothing to /// read and took the emu mutex instead — the defect this whole change fixes. diff --git a/docs/audio.md b/docs/audio.md index 507406a..e3a1dfb 100644 --- a/docs/audio.md +++ b/docs/audio.md @@ -235,3 +235,186 @@ crate (`docs/rsp.md`, ADR 0002). The *host*-rate resample (N64 output rate → t - **Determinism** — same seed + ROM + input ⇒ bit-identical stream: for the AI (`audio_play_rom.rs`) and for the mixer's PCM output (`mixer_microcode.rs`). **Done.** + +## The chopping, measured at both boundaries + +**User report:** audio plays ~1 s, then ~1 s of silence, repeating. +**Status:** root cause identified and measured; the *period* in the report does +not reproduce. Recorded here because a symptom description that survives into +three documents becomes the thing people design against. + +Two probes, both against Super Mario 64, both committed so the numbers are +re-runnable rather than remembered. + +**Provenance for every figure in this section.** These are host-sensitive, and +without this block they are anecdotes: + +| | | +| --- | --- | +| ROM | Super Mario 64 (USA), SHA-256 `17ce0773…bb21d91` (local corpus, gitignored) | +| host | Intel i9-10850K (10C/20T, 3.6 GHz base / 5.2 GHz boost), Linux 7.1.5 | +| toolchain | `rustc 1.96.0 (ac68faa20 2026-05-25)`, `--release` | +| build | default features for the device-boundary test; `fast-exec,fast-scheduler` for `audio_probe` — **the two are not comparable to each other**, which is why each table names its build | +| tree | `52600ea` | +| kind | **differential** over the timed window in every case: counters are cumulative from power-on and both harnesses subtract a baseline captured after warm-up | +| audio | 48 kHz host rate, fixed rather than device-negotiated, so no sound card is required | + +The two builds differ deliberately: `audio_probe` measures the *core* and wants +the fast path's ~15.7 FPS, while the device-boundary test measures the *shipped +default* at ~8.5 FPS. Reading a supply ratio from one against a frame rate from +the other is the mistake this table exists to prevent. + +| probe | boundary | how to run | +| --- | --- | --- | +| `crates/rustyn64-frontend/examples/audio_probe.rs` | the emulated AI, before the ring | `RUSTYN64_PROBE_ROM=… cargo run --release --example audio_probe --features fast-exec,fast-scheduler` | +| `emu_thread::tests::measure_audio_gaps_at_the_device_boundary` | the device callback, after the ring | `RUSTYN64_PROBE_ROM=… cargo test -p rustyn64-frontend --release --lib measure_audio_gaps -- --ignored --nocapture` | + +### What the emulated machine produces — it is not the AI + +| | | +| --- | --- | +| frames carrying audible samples | **108 / 120** (the 12 are contiguous, at the start, before the game's audio engine begins) | +| `Audio::underruns` over the window | **3** | +| samples staged per frame | **1600**, exactly `output_rate / 60 * 2` | +| supply ratio | **26.1%**, against `fps / 60 = 26.1%` | + +**So the emulated AI does not gap**, and the "supply is `fps / 60`" claim in +`audio.rs` is now measured rather than asserted. The competing hypothesis — that +the game's audio DMA is starving inside the machine, which would be an emulation +defect no host buffering could fix — is **refuted**: the stream is continuous +once it starts, and the underrun counter barely moves. + +### What the device receives + +At the device boundary, with the shipped 0.25 s ring and a 1024-frame callback: + +| | | +| --- | --- | +| callbacks fully fed | **0 / 469** | +| callbacks fully empty | **384 / 469** | +| samples delivered | **14.2%** (default build, ~8.5 FPS — `fps / 60 = 14.2%`) | +| silent runs | mean **95 ms**, max **128 ms** | + +**The reported ~1 s period is off by an order of magnitude.** The measured chop +is ~10 Hz, and its period is one emulated frame plus the pacer's yield — *not* +the ring's 0.25 s capacity, which an earlier note had guessed. Both halves of +that guess were wrong, and neither was checked before it was written down. + +### Why no buffering fixes it + +Supply is `fps / 60` by construction: `EmuCore::produce_audio` stages exactly one +emulated frame of audio per emulated frame, and the device consumes in wall-clock +time. A ring cannot emit samples that were never produced. The only levers are: + +1. **make the core faster** — `docs/performance.md` records that 60 FPS is out of + reach for this execution model, and that the entire declined optimization + backlog is worth ~1.12x; +2. **an explicit slow-running audio policy** — resample to the speed actually + achieved (continuous, heavily pitch-shifted), or mute below a speed threshold; +3. **accept the chopping**, which is what ships today. + +That is a product decision, not a defect, and it is recorded here rather than +silently resolved. + +### The rate-control servo does not exist + +`audio.rs` describes a servo that "nudges the produce rate to keep the ring near +half-full", and `AudioRing::occupancy` is documented as existing to feed it. +**`occupancy` has no callers outside its own module.** The accessor was written +for a consumer that was never built, and three doc comments describe it as though +it runs. Whichever policy above is chosen, it is the servo's slot that would hold +it. + +### One tempting fix, refuted by measurement + +The pacer sleeps a full frame period after **every** frame while already ~85 ms +behind (`emu_thread::Schedule::snap_if_behind` sets `target = now + period`). +That is 17.7 ms of idle on a 100 ms frame — confirmed two ways: `frame_bench` +measures **99.955 ms** unpaced, the pacer delivers **117.6 ms**. + +Shrinking that yield to 2 ms was built and measured A-B-A: + +| | frames / 10 s | samples delivered | UI emu-lock p50 | +| --- | --- | --- | --- | +| A — full-period yield (shipped) | 85 | 14.2% | **664 ns** | +| B — 2 ms yield | 96–97 | 16.0–16.2% | **76.5 ms** | +| A — repeat | 85 | 14.2% | 614 ns | + +**1.14x throughput, and it is not worth taking.** The UI's median wait for the +emu mutex goes from sub-microsecond to 76 ms, and the stand-in UI thread +completed 98 iterations instead of 173 in the same window. The yield is +*load-bearing*: it is the only interval in which anything else can take the emu +mutex, because the pacer holds it for the whole frame. The hypothesis that it was +vestigial is refuted. + +The real unlock is architectural: `emu_thread`'s own header says "**the winit +thread never takes the emu mutex**", and `app.rs` takes it in six places +(ROM load, save-state, pause, reset). Route those through the existing +`SaveStateControls`-style request queue and the yield stops being a UI window, at +which point the 1.14x is available for free. That needs its own change and is not +attempted here. + +## The fix that shipped: stretch, don't chop + +**Policy chosen:** continuous audio at the wrong pitch, over chopped audio at the +right pitch. Of the three levers above, (1) is unavailable and (3) was what +shipped; this is (2). + +`emu_thread::AudioServo` stretches each emulated frame's audio over the +wall-clock time that frame actually took. The samples are the same samples — the +servo cannot manufacture the missing 86%, and nothing can — they are simply spent +over the whole frame instead of over `1/60 s` followed by silence. A core at 14% +speed therefore sounds like a tape running at 14%: continuous, two and a half +octaves down. + +### How it decides + +| term | source | why | +| --- | --- | --- | +| feed-forward | EMA of the measured wall-clock interval between produced frames | correct on the *first* frame; an occupancy integrator covering a 7x range would take seconds to converge | +| trim | ring occupancy against half-full | removes residual drift, which the feed-forward term cannot see because it does not know what is already banked | + +Clamped to `[1.0, MAX_AUDIO_STRETCH]`. It **never compresses below real time**: a +core running faster than 60 FPS is already oversupplying, and the ring's +drop-oldest is the right answer there. `MAX_AUDIO_STRETCH = 12.0` bounds it at +5 FPS — below that the audio chops again rather than becoming an unrecognizable +drone that also pins the ring. + +### Measured, same harness as the defect + +| | before | after | +| --- | --- | --- | +| callbacks fully fed | **0 / 469** | **412 / 469** | +| callbacks fully empty | 384 / 469 | **34 / 469** | +| samples delivered | **14.2%** | **90.9%** | +| ...second half only (steady state) | 14.2% | **100.0%** | +| silent runs | 86, mean 95 ms | 14, mean 52 ms | +| first fully-fed callback | never | **#15 (320 ms in)** | +| UI emu-lock p50 | 664 ns | 590 ns (unchanged) | +| pacer frames / 10 s | 85 | 85 (unchanged) | + +**Steady state is 100%.** The whole-window 90.9% is the ramp from an empty ring +at startup, which is why the harness reports the second half separately — a +single figure charges a one-off transient to continuous quality. + +### The trim gain is measured, not tuned + +0.2, 0.4 and 0.6 were each run. **All three reach 100.0% steady state and all +three reach their first fully-fed callback at #15.** The only difference is the +whole-window figure (90.6 / 91.3 / 91.9%), which is dominated by the ramp. +Picking 0.6 for that 1.3-point edge would be tuning against a transient, so the +**lowest** gain ships: a larger one makes the pitch hunt audibly and nothing was +bought with it. + +### What it does not change + +- **Determinism.** The stretch is applied in the frontend resampler, which + ADR 0004 already designates as the non-deterministic host-timing stage. The + core's emitted stream (`Bus::drain_audio_samples`) is untouched, so + `audio_play_rom` and `mixer_microcode` — which pin the *core* PCM — are + unaffected, and the save-state trace compare does not read the resampled f32. +- **Anything without a ring.** With `ring: None` the servo is never consulted and + the core keeps its default `1.0`, so headless builds and every test are + byte-identical to before. +- **The pacer.** Frames produced per second is unchanged (85 both ways); this + trades no throughput.