From 8340a4667e5a2a46652df7ba075301d62ec3dc6f Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Sat, 1 Aug 2026 12:29:10 -0400 Subject: [PATCH 1/3] test(audio): measure the chopping at both boundaries instead of asserting it audio.rs already named the cause -- supply is fps/60 -- and had never measured it. It also repeated the user's "~1 s on / ~1 s off" as fact and guessed that the period was the ring's 0.25 s capacity. Two probes now settle all three claims, and only the first survives. examples/audio_probe.rs (core side, before the ring): the emulated AI stream is CONTINUOUS -- 108/120 frames audible, the 12 silent ones contiguous at the start, 3 underruns -- staging exactly rate/60 samples per frame, supply 26.1% against fps/60 = 26.1%. This refutes the competing hypothesis that the game's audio DMA starves inside the machine, which would have been an emulation defect rather than a speed consequence. measure_audio_gaps_at_the_device_boundary (device side, after the ring): 0/469 callbacks fully fed, 14.2% of samples delivered, silent runs mean 95 ms and max 128 ms. So the chop is ~10 Hz, an ORDER OF MAGNITUDE off the reported ~1 s, and its period is one emulated frame plus the pacer's yield -- not the ring capacity. Both halves of the recorded guess were wrong and neither had been checked. Also records a tempting fix that MUST NOT be taken. The pacer sleeps a full frame period after every frame while ~85 ms behind (99.955 ms unpaced via frame_bench, 117.6 ms paced). Shrinking it to 2 ms measures A-B-A at 1.14x with audio 14.2% -> 16.2% -- and takes the UI's median emu-mutex wait from 664 ns to 76.5 ms. The yield is load-bearing, not vestigial: it is the only window in which anything else can take the emu mutex, because the pacer holds it for the whole frame. Reverted. No production code changes. The fix is a policy choice (slow-running audio) plus an architectural one (stop app.rs taking the emu mutex in six places, which emu_thread's own header already claims it does not). --- .../rustyn64-frontend/examples/audio_probe.rs | 210 ++++++++++++++++++ crates/rustyn64-frontend/src/audio.rs | 37 ++- crates/rustyn64-frontend/src/emu_thread.rs | 202 +++++++++++++++++ docs/audio.md | 100 +++++++++ 4 files changed, 540 insertions(+), 9 deletions(-) create mode 100644 crates/rustyn64-frontend/examples/audio_probe.rs diff --git a/crates/rustyn64-frontend/examples/audio_probe.rs b/crates/rustyn64-frontend/examples/audio_probe.rs new file mode 100644 index 00000000..0877a809 --- /dev/null +++ b/crates/rustyn64-frontend/examples/audio_probe.rs @@ -0,0 +1,210 @@ +//! **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() { + 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) + .unwrap_or_else(|e| panic!("probe ROM did not 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; + } + } + + 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()); +} + +/// 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) { + 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) - log.first().map_or(0, |f| f.underruns); + + // 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 8c615409..8576fbac 100644 --- a/crates/rustyn64-frontend/src/audio.rs +++ b/crates/rustyn64-frontend/src/audio.rs @@ -18,17 +18,36 @@ //! 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. +//! +//! 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. **The rate-control servo described above does not exist**: +//! [`AudioRing::occupancy`] has no callers outside this module. use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Arc, Mutex}; diff --git a/crates/rustyn64-frontend/src/emu_thread.rs b/crates/rustyn64-frontend/src/emu_thread.rs index f104b034..3a42fec8 100644 --- a/crates/rustyn64-frontend/src/emu_thread.rs +++ b/crates/rustyn64-frontend/src/emu_thread.rs @@ -404,6 +404,208 @@ mod tests { ); } + /// **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 — cpal's + /// usual default), so the callback cadence is ~21 ms like a real one. + 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); + + 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. + let real = buf.iter().rposition(|s| *s != 0.0).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 + ); + 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 507406a5..90606bcf 100644 --- a/docs/audio.md +++ b/docs/audio.md @@ -235,3 +235,103 @@ 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: + +| 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. From 52600ea9ed3813f525b8f977bd67488235248461 Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Sat, 1 Aug 2026 12:59:32 -0400 Subject: [PATCH 2/3] fix(audio): stretch each frame's audio over the time the frame took The device was offered fps/60 of what it consumes and silence for the rest -- 14.2% measured, with 0 of 469 callbacks fully fed. produce_audio stages exactly one emulated frame of audio per emulated frame, so no buffering strategy can make up the difference. AudioServo stretches that frame's audio across the wall-clock interval the frame actually took: feed-forward from an EMA of the measured interval, trimmed by ring occupancy toward half-full, clamped to [1.0, MAX_AUDIO_STRETCH]. The samples are the same samples, spent over the whole frame rather than a sixtieth of it, so a slow core sounds like a slow tape instead of a stutter. The maintainer chose continuity over pitch when given the three options. 14.2% -> 90.9% delivered, 100.0% in steady state; the shortfall is the startup ramp from an empty ring, which the harness now reports separately because a single figure charges a one-off transient to steady quality. Frames per second (85) and UI emu-lock latency (p50 590 ns) are both unchanged -- this trades no throughput. TRIM_GAIN is measured, not tuned: 0.2/0.4/0.6 all reach 100% steady state and all reach their first fully-fed callback at #15, differing only in the ramp-dominated whole-window figure. The lowest ships, because a larger gain makes the pitch hunt and bought nothing. The wiring test seeds the core's stretch with a value outside the servo's clamp range, because a ROM-less core legitimately asks for 1.0 -- which is also the default, so asserting the value alone cannot tell "applied" from "never written". Both mutations verified red: deleting set_audio_stretch, and never consulting the servo. Determinism untouched: the stretch applies in the frontend resampler, which ADR 0004 already designates as the non-deterministic host-timing stage. The core's emitted stream is unchanged, so audio_play_rom and mixer_microcode are unaffected, and with no ring the servo never runs. --- CHANGELOG.md | 24 ++ crates/rustyn64-frontend/src/audio.rs | 16 +- crates/rustyn64-frontend/src/emu.rs | 136 ++++++++- crates/rustyn64-frontend/src/emu_thread.rs | 311 ++++++++++++++++++++- docs/audio.md | 65 +++++ 5 files changed, 541 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e4ae170d..0b0e6653 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/src/audio.rs b/crates/rustyn64-frontend/src/audio.rs index 8576fbac..48723665 100644 --- a/crates/rustyn64-frontend/src/audio.rs +++ b/crates/rustyn64-frontend/src/audio.rs @@ -43,11 +43,17 @@ //! 0.25 s capacity, so "the ~1 s period is the ring's capacity" was wrong twice //! over. //! -//! 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. **The rate-control servo described above does not exist**: -//! [`AudioRing::occupancy`] has no callers outside this module. +//! 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 140d341b..0438604e 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 3a42fec8..79949a44 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,156 @@ 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. /// @@ -578,6 +867,22 @@ mod tests { " 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(), diff --git a/docs/audio.md b/docs/audio.md index 90606bcf..ef4a56df 100644 --- a/docs/audio.md +++ b/docs/audio.md @@ -335,3 +335,68 @@ thread never takes the emu mutex**", and `app.rs` takes it in six places `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. From 77f671092bfbc88270a0b167240d1ac6b46e9f84 Mon Sep 17 00:00:00 2001 From: DoubleGate Date: Sat, 1 Aug 2026 13:27:20 -0400 Subject: [PATCH 3/3] fix(audio): the delivered-percentage counted a zero crossing as underrun Four review findings, three of which are real defects in the measurement rather than in the code it measures. `rposition(|s| *s != 0.0)` treated an exact zero at the tail of a callback as the start of underrun silence. Real audio crosses zero, so some fully-fed callbacks were scored as partial. It biases DOWNWARD and applied to both legs equally, so the 14.2% -> 90.9% comparison held, but both absolute figures were pessimistic. Now thresholded at the same 1e-4 floor audio_probe.rs uses, and the numbers move to 14.2% -> 90.1%. The underrun baseline was taken from the FIRST TIMED FRAME rather than from before the loop, so any underrun that frame recorded was silently dropped. Captured before the loop now. The documented value is still 3 for this ROM -- the method was wrong and the number happened not to be, which is worth stating rather than quietly correcting. "1024 frames -- cpal's usual default" is an undocumented claim about cpal 0.18, which defers BufferSize::Default to the host and device. It is a representative callback size and the comment now says so; the delivered percentage is a ratio and does not depend on it. docs/audio.md gains the provenance block its own rules require: ROM SHA-256, host, toolchain, build configuration, tree, and the fact that every figure is differential. It also states outright that the two harnesses run different builds (fast-exec vs default) and must not be cross-read -- the mistake the table exists to prevent. Not adopted: making the env-var and file-read failures typed errors. Those are harness misconfiguration, not untrusted input, and a probe that cannot start must stop loudly. The ROM CONTENTS are parsed data and now do return a typed error, which is where the rule actually bites. --- .../rustyn64-frontend/examples/audio_probe.rs | 25 +++++++++++++++---- crates/rustyn64-frontend/src/emu_thread.rs | 25 ++++++++++++++++--- docs/audio.md | 20 ++++++++++++++- 3 files changed, 61 insertions(+), 9 deletions(-) diff --git a/crates/rustyn64-frontend/examples/audio_probe.rs b/crates/rustyn64-frontend/examples/audio_probe.rs index 0877a809..609095be 100644 --- a/crates/rustyn64-frontend/examples/audio_probe.rs +++ b/crates/rustyn64-frontend/examples/audio_probe.rs @@ -65,7 +65,11 @@ struct FrameAudio { underruns: u64, } -fn main() { +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 \ @@ -77,7 +81,7 @@ fn main() { let mut core = EmuCore::new(0); core.set_output_rate(OUTPUT_RATE); core.load_rom(&raw) - .unwrap_or_else(|e| panic!("probe ROM did not boot: {path}: {e:?}")); + .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. @@ -93,6 +97,10 @@ fn main() { } } + // 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 { @@ -107,7 +115,14 @@ fn main() { } let wall = t0.elapsed().as_secs_f64(); - report(&path, &log, wall, core.system().bus.audio.sample_rate()); + report( + &path, + &log, + wall, + core.system().bus.audio.sample_rate(), + underruns_before, + ); + Ok(()) } /// Print the evidence. Split from `main` so the measurement and its @@ -116,10 +131,10 @@ fn main() { 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) { +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) - log.first().map_or(0, |f| f.underruns); + 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. diff --git a/crates/rustyn64-frontend/src/emu_thread.rs b/crates/rustyn64-frontend/src/emu_thread.rs index 79949a44..8c95b430 100644 --- a/crates/rustyn64-frontend/src/emu_thread.rs +++ b/crates/rustyn64-frontend/src/emu_thread.rs @@ -717,14 +717,24 @@ mod tests { #[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 — cpal's - /// usual default), so the callback cadence is ~21 ms like a real one. + /// 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"); @@ -791,7 +801,16 @@ mod tests { // 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. - let real = buf.iter().rposition(|s| *s != 0.0).map_or(0, |i| i + 1); + // + // 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(); diff --git a/docs/audio.md b/docs/audio.md index ef4a56df..e3a1dfb7 100644 --- a/docs/audio.md +++ b/docs/audio.md @@ -244,7 +244,25 @@ 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: +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 | | --- | --- | --- |