diff --git a/CHANGELOG.md b/CHANGELOG.md index 5f5252c2..db084505 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,71 @@ cycle-accurate core later replaced. ## [Unreleased] +### Added + +- **Audio provenance — point at a moment in the frame and read why it sounds + like that.** The APU counterpart of pixel provenance, and deliberately the + same shape: a per-register write attribution answering *what wrote this, and + from which instruction*, and a per-CPU-cycle mix trace answering *what were + the channels actually doing*. Surfaced at **Tools → Audio → Audio + Provenance**. Output-only, runtime-default-off, and not serialized, so the + deterministic audio contract is unaffected whether it is armed or not. + + Every ingredient but one already shipped — the Audio Scope plots the + waveforms, the Audio Mixer sets the gains, `Apu::pulse1_out()` and its + siblings expose live channel outputs, and the Event Viewer already classifies + `$4000-$4017` writes as `EventKind::ApuWrite`. What existed nowhere is the + link from a sample back to the instruction that caused it: `EventRec` carries + `kind / scanline / dot / addr / value` — no PC, no CPU cycle — and is + scanline-oriented rather than sample-oriented. So the event log is the + interception *point* this reuses; it is not the record. + + The trace is per **CPU cycle**, the cadence at which the mix is genuinely + computed, rather than per output sample. `blip` decimates to 44.1 kHz — about + one sample per 40.6 CPU cycles — and an output sample is a weighted sum of + transitions across the filter kernel, not a copy of one instant. Recording at + output rate would mean picking which of those ~40 mixes "is" the sample, which + the signal chain cannot answer; the panel reports the cycle window and says so + instead. `MIX_CAP` is sized from **Dendy** (35,464 cycles/frame), not the NTSC + figure that comes to mind first, and reports `truncated()` rather than + returning a short buffer that looks complete. + + Register rows carry their **side-band effects**, because naming the right + instruction and then describing the wrong effect is its own failure: a write + to `$4003` does not merely set the period, it also loads the length counter, + resets the duty sequencer and restarts the envelope. Those annotations were + confirmed against this emulator's own implementation, not from memory. + + **The trap this feature inherited was closed in the same change as the + feature, not after a bug report.** Pixel provenance shipped non-functional for + four releases because run-ahead's per-frame rollback cleared the store before + the frontend released the emulator lock, so the UI could never observe a + populated record — and a comment asserted the opposite, which is what stopped + anyone checking. Audio provenance rides the identical rollback, so + `take_audio_provenance` / `put_audio_provenance` carry the state around + `restore_quiet` in `RunAhead::finish` from the outset. Save-state loads and + netplay rollback still clear, unchanged: those are genuine timeline changes, + and run-ahead's is not. The regression test drives the real produce path at + `run_ahead = 1` — the default — and is mutation-checked. Both it and its + control are floored at 20,000 records rather than "non-empty", because the + APU's reset sequence alone produces eight, so a non-emptiness check would pass + on a run that emulated nothing. + + Spec: `docs/audio-provenance.md`. `rustynes-apu` gains a `debug-hooks` + feature, forwarded from the core's. + +### Changed + +- **Audio provenance costs the shipped default nothing when it is not armed.** + The feature is compiled into every build (the frontend enables the core's + `debug-hooks` unconditionally), so "default-off" describes the runtime arm + rather than the code. Two separate mechanisms were found charging the APU + hot path while disarmed — the mix record was being built before the arm was + tested, and the recording body was being inlined into the hot mix path — and + both are fixed; the disarmed path measures at baseline. The full measurement + chronology, including a diagnosis that was made, measured and rejected, is in + `docs/performance.md` §v2.3.7 C2 rather than here. + ### Fixed - **VRC7 save states now carry the FM synthesizer, so rewind no longer garbles diff --git a/crates/rustynes-apu/Cargo.toml b/crates/rustynes-apu/Cargo.toml index a57b4fb3..dbd71781 100644 --- a/crates/rustynes-apu/Cargo.toml +++ b/crates/rustynes-apu/Cargo.toml @@ -23,6 +23,16 @@ workspace = true # would then quietly opt every consumer in to `std`, masking no_std regressions # from cross-target CI gates that build with `--no-default-features`. std = [] +# v2.3.7 "Overtone" — audio provenance: per-register write attribution (which +# instruction wrote `$4000-$4017`) and a per-CPU-cycle trace of the channel +# outputs actually mixed. Mirrors `rustynes-ppu/debug-hooks`, and like it the +# feature is only half the gate: `rustynes-core` forwards it and the frontend +# enables it unconditionally, so **the thing that is default-off is the runtime +# ARM**, a lazily-allocated `Option` whose disarmed cost is one discriminant +# test per register write and per mixed cycle. Output-only: nothing here is read +# back into synthesis or carried in the save state, so the shipped default is +# byte-identical and the determinism contract is untouched. +debug-hooks = [] [dependencies] bitflags.workspace = true diff --git a/crates/rustynes-apu/src/apu.rs b/crates/rustynes-apu/src/apu.rs index 0b7b0b22..baa32e51 100644 --- a/crates/rustynes-apu/src/apu.rs +++ b/crates/rustynes-apu/src/apu.rs @@ -305,6 +305,15 @@ pub struct Apu { /// audio — the visualization samples a copy, exactly like the base-channel /// `*_out()` DAC accessors already do. pub(crate) last_external: f32, + + /// v2.3.7 "Overtone" — audio provenance, behind ONE pointer. + /// + /// `None` until armed via [`Apu::set_audio_provenance`]. Consolidated into a + /// single `Option>` after `apu_throughput` measured +9% on the + /// DISARMED path with this state spread across four inline fields — see + /// `crate::provenance::AudioProvenance`. + #[cfg(feature = "debug-hooks")] + pub(crate) audio_prov: Option>, } /// All [`Apu::channel_mask`] bits set — every channel audible (the default and @@ -383,9 +392,185 @@ impl Apu { channel_mask: CHANNEL_MASK_ALL, channel_gain: CHANNEL_GAIN_UNITY, last_external: 0.0, + #[cfg(feature = "debug-hooks")] + audio_prov: None, + } + } + + // ----------------------------------------------------------------- + // v2.3.7 "Overtone" — audio provenance (output-only, off by default) + // ----------------------------------------------------------------- + + /// Record one mixed CPU cycle — the OUTLINED half. + /// + /// Called from both mix paths so the fast default-configuration + /// specialization and the gated general path produce the same trace: a + /// provenance record that existed on only one of two byte-identical paths + /// would be a trap for whoever next changed the other. + /// + /// # Why `#[cold]` and `#[inline(never)]` are load-bearing + /// + /// This function is measurement-driven twice over, and the second lesson is + /// the less obvious one. + /// + /// The FIRST version built the `MixRecord` before testing whether + /// provenance was armed, so a DISARMED build recomputed all five channel + /// outputs every CPU cycle — and `Pulse::output` is not free (it calls + /// `muted()`, which calls `sweep_target()`). `apu_throughput` measured + /// **+14% to +23%** in the feature-on/arm-off configuration the shipped + /// frontend runs. Hoisting the arm check to the top fixed that. + /// + /// It was NOT enough. With the check first, a quiet-host A/B still measured + /// **+7.98% / +2.88% / +11.03%** on the three `apu_throughput` workloads + /// (order-bias control: +0.11% / +0.76% / +0.67%, so the deltas are real). + /// The absolute costs — +33 µs, +15 µs, +65 µs — are wildly non-uniform, + /// which a per-cycle branch cannot produce: a constant branch costs a + /// constant number of cycles. The cause was that this body was still being + /// INLINED into `tick_with_external`. The five `output()` calls sat in the + /// hot function even though the branch skipped over them, inflating it past + /// the point where the mixer and the channel ticks kept their registers and + /// their I-cache line. + /// + /// So the hot path now contains exactly one null test, and everything else + /// lives out of line behind it. `#[cold]` additionally tells LLVM to lay + /// this block out away from the fall-through path. It pessimizes the ARMED + /// case, which is the correct trade: armed is an interactive debugging mode + /// and disarmed is what every user runs. + #[cfg(feature = "debug-hooks")] + #[cold] + #[inline(never)] + fn record_mix_armed(&mut self, mixed: f32, external: f32) { + let rec = crate::provenance::MixRecord { + mixed, + external, + pulse1: self.pulse1.output(), + pulse2: self.pulse2.output(), + triangle: self.triangle.output(), + noise: self.noise.output(), + dmc: self.dmc.output(), + }; + if let Some(p) = self.audio_prov.as_mut() { + p.mix_trace.push(rec); } } + /// Arm or disarm audio provenance. + /// + /// Arming allocates both stores; disarming frees them. Mirrors + /// `Ppu::set_pixel_provenance`, including that re-arming an already-armed + /// APU is a no-op rather than a silent wipe — the frontend re-asserts the + /// arm every frame (a lesson from the pixel panel, whose edge-triggered + /// mirror desynced permanently the moment a ROM load installed a fresh + /// core). + #[cfg(feature = "debug-hooks")] + pub fn set_audio_provenance(&mut self, enabled: bool) { + if enabled { + if self.audio_prov.is_none() { + self.audio_prov = Some(alloc::boxed::Box::new( + crate::provenance::AudioProvenance::new(), + )); + } + } else { + self.audio_prov = None; + } + } + + /// Whether audio provenance is armed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub const fn audio_provenance_armed(&self) -> bool { + self.audio_prov.is_some() + } + + /// The per-register write attribution, or `None` when disarmed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn register_attribution(&self) -> Option<&crate::provenance::RegisterAttribution> { + self.audio_prov.as_ref().map(|p| &p.reg_attrib) + } + + /// The per-CPU-cycle mix trace, or `None` when disarmed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn mix_trace(&self) -> Option<&crate::provenance::MixTrace> { + self.audio_prov.as_ref().map(|p| &p.mix_trace) + } + + /// Begin a new frame's mix trace, anchored at `first_cycle`. + /// + /// The register attribution is deliberately NOT cleared here: "which + /// instruction last wrote `$4003`" is a question whose answer legitimately + /// predates the current frame, and clearing it every frame would report a + /// register nobody has touched this frame as never written. + #[cfg(feature = "debug-hooks")] + pub fn begin_audio_provenance_frame(&mut self, first_cycle: u64) { + if let Some(p) = self.audio_prov.as_mut() { + p.mix_trace.clear(first_cycle); + } + } + + /// Forget the register attribution history. Called on a cold boot, where + /// the history it describes genuinely ended. + #[cfg(feature = "debug-hooks")] + pub fn clear_audio_provenance_history(&mut self) { + if let Some(p) = self.audio_prov.as_mut() { + p.reg_attrib.clear(); + } + } + + /// Attribute a write in `$4000-$4017` that the bus does NOT route through + /// [`Self::write_register`]. + /// + /// Two addresses in the range are not APU registers and are handled + /// entirely on the bus: `$4014` (OAM DMA, which arms a burst) and `$4016` + /// (controller strobe, which is buffered to the next M2-low boundary). + /// `Bus::write` dispatches only `$4000-$4013 | $4015 | $4017` to + /// `write_register`, so the attribution recorded there can never see those + /// two — yet the table reserves slots for them, because the range is what + /// the bus already classifies as an APU write and punching a hole in it + /// would invite off-by-one arithmetic at every call site. + /// + /// Without this entry point those two slots would stay permanently empty + /// while the docs claimed they were tracked. This records the cause exactly + /// as `write_register` would, and dispatches nothing — the emulation of both + /// addresses stays wherever the bus already implements it. + #[cfg(feature = "debug-hooks")] + pub const fn record_bus_handled_register_write(&mut self, addr: u16, value: u8) { + if let Some(p) = self.audio_prov.as_mut() { + p.reg_attrib + .record(addr, p.attrib_pc, p.attrib_cycle, value); + } + } + + /// Push the writing instruction's PC + cycle down, mirroring the PPU's + /// write-attribution context. Called once per instruction by the core. + #[cfg(feature = "debug-hooks")] + pub const fn set_attrib_context(&mut self, pc: u16, cycle: u64) { + // No-op when disarmed: nothing reads these, so skipping the stores keeps + // the disarmed per-instruction cost at one null test. + if let Some(p) = self.audio_prov.as_mut() { + p.attrib_pc = pc; + p.attrib_cycle = cycle; + } + } + + /// Lift both stores out for a same-timeline restore (run-ahead), leaving the + /// APU disarmed. See [`crate::provenance::AudioProvenanceStash`] for why + /// this exists at all. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn take_audio_provenance(&mut self) -> crate::provenance::AudioProvenanceStash { + crate::provenance::AudioProvenanceStash { + state: self.audio_prov.take(), + } + } + + /// Put back stores taken by [`Self::take_audio_provenance`]. + #[cfg(feature = "debug-hooks")] + pub fn put_audio_provenance(&mut self, stash: crate::provenance::AudioProvenanceStash) { + self.audio_prov = stash.state; + } + /// Reset (warm). Per nesdev: most APU state is preserved across reset /// except `$4015` is cleared (channels disabled, DMC silenced). /// @@ -412,6 +597,15 @@ impl Apu { self.reset_4017_value = last; self.reset_4017_delay = 2; self.write_register(0x4015, 0x00); + // v2.3.7 — that write went through the ordinary CPU path, which just + // attributed it to whatever instruction was last latched. No instruction + // caused it: this models the warm-reset silencing of the channels. + // Correct the origin so the panel reports hardware rather than naming an + // innocent PC. (Caught in review of the PR that added the feature.) + #[cfg(feature = "debug-hooks")] + if let Some(p) = self.audio_prov.as_mut() { + p.reg_attrib.record_reset(0x4015, p.attrib_cycle, 0x00); + } self.pending_dmc_dma = false; self.dmc_dma_is_load = false; self.dmc_dma_short = false; @@ -1086,6 +1280,10 @@ impl Apu { self.noise.output(), self.dmc.output(), ) + external; + #[cfg(feature = "debug-hooks")] + if self.audio_prov.is_some() { + self.record_mix_armed(mixed, external); + } self.blip.add_sample(mixed); // Nothing follows the general path's `add_sample` but comments -- // the get/put flip moved to `dmc_tick_end` under M-2 -- so there is @@ -1140,6 +1338,19 @@ impl Apu { scale(3, gate(3, self.noise.output()), 15), scale(4, gate(4, self.dmc.output()), 127), ) + if mask & (1 << 5) != 0 { ext } else { 0.0 }; + #[cfg(feature = "debug-hooks")] + if self.audio_prov.is_some() { + // RAW `external`, not the gained `ext`, and not zero when the mask + // bit clears it. The five channel fields are already the raw + // pre-gate outputs, so recording a gain-scaled or mask-zeroed + // expansion value would make ONE field follow the user's mixer + // sliders while five describe the chip -- and would make this path + // disagree with the fast path, which records the raw value. Review + // caught the disagreement; this resolves it toward the documented + // semantic rather than toward the local variable that happened to + // be in scope. + self.record_mix_armed(mixed, external); + } self.blip.add_sample(mixed); // v2.0 interleaved-DMA Phase A: toggle the global get/put flip-flop once @@ -1550,6 +1761,14 @@ impl Apu { /// CPU register write (`$4000-$4017` excluding `$4014`). pub fn write_register(&mut self, addr: u16, value: u8) { + // v2.3.7 "Overtone" — attribute the write BEFORE dispatching it, so the + // recorded value is what the CPU put on the bus rather than whatever a + // channel decided to keep. One `Option` test when disarmed. + #[cfg(feature = "debug-hooks")] + if let Some(p) = self.audio_prov.as_mut() { + p.reg_attrib + .record(addr, p.attrib_pc, p.attrib_cycle, value); + } match addr { 0x4000 => self.pulse1.write_ctrl(value), 0x4001 => self.pulse1.write_sweep(value), diff --git a/crates/rustynes-apu/src/lib.rs b/crates/rustynes-apu/src/lib.rs index 157be09f..018bc1ca 100644 --- a/crates/rustynes-apu/src/lib.rs +++ b/crates/rustynes-apu/src/lib.rs @@ -44,6 +44,8 @@ mod length; mod mixer; mod noise; mod opll; +#[cfg(feature = "debug-hooks")] +pub mod provenance; mod pulse; mod snapshot; mod triangle; diff --git a/crates/rustynes-apu/src/provenance.rs b/crates/rustynes-apu/src/provenance.rs new file mode 100644 index 00000000..28e7dc59 --- /dev/null +++ b/crates/rustynes-apu/src/provenance.rs @@ -0,0 +1,657 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +//! Audio provenance (v2.3.7 "Overtone") — why does this moment sound like that? +//! +//! The APU analogue of the PPU's `rustynes_ppu::provenance` (a plain code span, +//! not an intra-doc link: `rustynes-apu` does not depend on `rustynes-ppu`, and a +//! bracketed link to a crate outside the graph fails `RUSTDOCFLAGS=-D warnings` +//! while clippy stays green), and deliberately +//! built to the same shape: a **register-attribution** half that answers "what +//! wrote this, and from which instruction", and a **per-cycle mix trace** that +//! answers "what were the channels actually doing". +//! +//! # What was missing before this +//! +//! Every other ingredient already shipped. The frontend's audio scope plots the +//! per-channel waveforms, the audio mixer exposes per-channel gain, +//! [`crate::Apu::pulse1_out`] and its siblings expose live channel outputs, and +//! the trace logger has PC and cycle. What did not exist anywhere is the **link +//! between a sample and the instruction that caused it** — exactly the gap the +//! pixel-provenance design identified for video. +//! +//! # Cadence, and why it is per CPU cycle rather than per output sample +//! +//! The mix is computed **once per CPU cycle** (1.789 MHz NTSC) and handed to the +//! band-limited `blip` decimator, which produces output samples at 44.1 kHz — +//! about one per 40.6 CPU cycles. Recording at *output* rate would therefore +//! require choosing which of those 40 mixes "is" the sample, and band-limited +//! synthesis makes that choice ill-posed: an output sample is a weighted sum of +//! transitions across the filter kernel, not a copy of one instant. +//! +//! So this records what was genuinely mixed, at the cadence it was mixed. The +//! panel maps a clicked output sample back to its CPU-cycle window; the doc says +//! plainly that the window is a kernel width, not a point. **A provenance tool +//! that answers a question it cannot actually answer is worse than one that +//! declines** — the whole argument v2.3.6 was built on. +//! +//! The cost is smaller than it sounds: 29,781 records per NTSC frame against the +//! pixel store's 61,440 — **0.48x the record count of the video side**. +//! +//! # Determinism +//! +//! Output-only. Nothing here is read back into synthesis, none of it is part of +//! the save state, and every store is behind a runtime arm that is off by +//! default. With the arm off the cost is one `Option` discriminant test per +//! register write and per mixed cycle. + +use alloc::boxed::Box; +use alloc::vec::Vec; + +/// First APU/IO register address covered by [`RegisterAttribution`]. +pub const REG_BASE: u16 = 0x4000; + +/// Number of register slots tracked: `$4000-$4017` inclusive. +/// +/// `$4014` (OAM DMA) and `$4016` (controller strobe) are inside the range and +/// are NOT APU registers. They are tracked anyway rather than punched out: the +/// range is what the bus already classifies as [`EventKind::ApuWrite`], keeping +/// one contiguous index space costs two slots, and a hole would be a permanent +/// invitation to off-by-one arithmetic at every call site. +/// +/// [`EventKind::ApuWrite`]: https://docs.rs/rustynes-core +pub const REG_COUNT: usize = 0x18; + +/// [`REG_COUNT`] as a `u16`, so address arithmetic never needs a cast. +pub const REG_COUNT_U16: u16 = 0x18; + +/// Largest CPU-cycle count in one frame across every supported region, which is +/// what [`MixTrace`] is sized for. +/// +/// Dendy is the worst case, not NTSC: 1,773,448 Hz / 50.007 fps = **35,464** +/// cycles per frame, against PAL's 33,247 and NTSC's 29,781. Sizing this from +/// the NTSC number — the one that comes to mind first — would silently truncate +/// the last 16% of every Dendy frame. +pub const MIX_CAP: usize = 36_864; + +// --------------------------------------------------------------------------- +// Register attribution — "what wrote $4003, and from where?" +// --------------------------------------------------------------------------- + +/// One register write: the byte, the CPU cycle, and the instruction that did it. +/// +/// `cycle` is the CPU cycle counter at the writing instruction, which is what +/// makes a record comparable against the Trace Logger and the Event Viewer for +/// the same frame. Mirrors `rustynes_ppu::provenance::WriteAttrib`, which +/// carries the same three fields for VRAM/OAM/palette bytes. +#[derive(Clone, Copy, Debug, Eq, PartialEq, Hash)] +pub struct RegWrite { + /// CPU cycle count at the write. + pub cycle: u64, + /// Program counter of the writing instruction. Meaningful only when + /// [`Self::origin`] is [`WriteOrigin::Instruction`]. + pub pc: u16, + /// The byte written, as the CPU put it on the bus. + pub value: u8, + /// What performed the write. + pub origin: WriteOrigin, +} + +/// What performed a register write. +/// +/// **Not every write to `$4000-$4017` comes from an instruction, and a +/// provenance tool that pretends otherwise is worse than no tool.** `Apu::reset` +/// performs an internal `write_register($4015, 0)` modelling the warm-reset +/// silencing of the channels. That is real hardware behaviour with no CPU +/// instruction behind it, and attributing it to whatever PC happened to be +/// latched would print a confident, specific, wrong answer — the exact failure +/// this feature exists to prevent, reproduced by the feature itself. +/// +/// Found in review of the PR that introduced audio provenance, before it +/// shipped. The alternative fixes were both worse: suppressing the record +/// entirely would leave the slot advertising the register's *previous* value +/// after reset genuinely changed it, and a sentinel PC would be indistinguishable +/// from a real write to address zero. +#[derive(Clone, Copy, Debug, Default, Eq, PartialEq, Hash)] +pub enum WriteOrigin { + /// A CPU instruction wrote it; `pc` names that instruction. + #[default] + Instruction, + /// The APU's own reset sequence wrote it. `pc` is not meaningful. + Reset, +} + +/// Storage-side mirror of [`RegWrite`] with a `Default`, so a slot array can be +/// built without inventing a meaningless public default PC. +#[derive(Clone, Copy, Debug, Default, Eq, PartialEq, Hash)] +struct RegWriteInner { + cycle: u64, + pc: u16, + value: u8, + origin: WriteOrigin, +} + +/// One attribution slot plus whether anything has been written yet. +/// +/// A `written` flag rather than a sentinel cycle, for the reason the PPU side +/// documents: **cycle 0 is a legitimate value** — the reset sequence performs +/// real writes — so a sentinel would silently misreport the earliest writes in a +/// run as "never written". +#[derive(Clone, Copy, Debug, Default, Eq, PartialEq, Hash)] +struct Slot { + rec: RegWriteInner, + written: bool, +} + +impl Slot { + const fn get(self) -> Option { + if self.written { + Some(RegWrite { + cycle: self.rec.cycle, + pc: self.rec.pc, + value: self.rec.value, + origin: self.rec.origin, + }) + } else { + None + } + } +} + +/// Last write to each of `$4000-$4017`, with its cause. +/// +/// **Last write, not a history.** One slot per address rather than a ring, +/// because the question this half answers is "what is the register holding, and +/// who put it there" — and a ring would need a retention policy nobody has a +/// principled value for. The Event Viewer already keeps the per-frame write +/// *sequence*; this keeps the per-register *cause*, which it does not. +#[derive(Clone, Debug)] +pub struct RegisterAttribution { + slots: [Slot; REG_COUNT], +} + +impl RegisterAttribution { + /// A fresh table with every slot unwritten. + #[must_use] + pub const fn new() -> Self { + Self { + slots: [Slot { + rec: RegWriteInner { + cycle: 0, + pc: 0, + value: 0, + origin: WriteOrigin::Instruction, + }, + written: false, + }; REG_COUNT], + } + } + + /// Forget every recorded write. + pub fn clear(&mut self) { + *self = Self::new(); + } + + /// Record a write to `addr`. Addresses outside `$4000-$4017` are dropped + /// rather than wrapping into an unrelated slot. + pub const fn record(&mut self, addr: u16, pc: u16, cycle: u64, value: u8) { + let Some(idx) = Self::index(addr) else { + return; + }; + self.slots[idx] = Slot { + rec: RegWriteInner { + cycle, + pc, + value, + origin: WriteOrigin::Instruction, + }, + written: true, + }; + } + + /// Record a write performed by the APU's own reset sequence. + /// + /// Overwrites whatever [`Self::record`] just stored for the same address, + /// which is deliberate: `Apu::reset` reaches the slot through the ordinary + /// `write_register` path, so the honest origin has to replace the + /// instruction attribution that path installs. The value and cycle are + /// genuine — the register really did change, at that time — and only the + /// claim about *who caused it* is corrected. + pub const fn record_reset(&mut self, addr: u16, cycle: u64, value: u8) { + let Some(idx) = Self::index(addr) else { + return; + }; + self.slots[idx] = Slot { + rec: RegWriteInner { + cycle, + pc: 0, + value, + origin: WriteOrigin::Reset, + }, + written: true, + }; + } + + /// The last write to `addr`, or `None` if the address is out of range or + /// nothing has written it since the last [`Self::clear`]. + #[must_use] + pub const fn get(&self, addr: u16) -> Option { + match Self::index(addr) { + Some(idx) => self.slots[idx].get(), + None => None, + } + } + + /// Map a register address to a slot index, or `None` when out of range. + const fn index(addr: u16) -> Option { + if addr < REG_BASE { + return None; + } + let idx = (addr - REG_BASE) as usize; + if idx < REG_COUNT { Some(idx) } else { None } + } +} + +impl Default for RegisterAttribution { + fn default() -> Self { + Self::new() + } +} + +// --------------------------------------------------------------------------- +// Mix trace — "what were the channels doing?" +// --------------------------------------------------------------------------- + +/// The five channel outputs that went into one mixed CPU-cycle sample, plus the +/// result. +/// +/// Channel values are the raw pre-mix outputs each channel presented — 0-15 for +/// the two pulses, the triangle and the noise, 0-127 for the DMC — which is what +/// the non-linear mixer consumes. They are NOT scaled by the frontend's mixer +/// gains: those are a presentation control, and recording post-gain values would +/// make the record describe the user's slider rather than the chip. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct MixRecord { + /// The mixed sample handed to the band-limited decimator, including any + /// expansion audio. + pub mixed: f32, + /// The expansion-audio contribution, RAW (`0.0` on a cartridge without one). + /// + /// Raw in the same sense as the five channel fields: before the frontend's + /// expansion gain and before the mixer mask. So on a muted or attenuated + /// expansion channel this reports what the cartridge produced, not what + /// reached `mixed` — consistent with `pulse1` reporting a muted pulse's + /// output rather than zero. Both mix paths record this same raw value; an + /// earlier revision recorded the gained value on one of them, which review + /// caught. + pub external: f32, + /// Pulse 1 output, 0-15. + pub pulse1: u8, + /// Pulse 2 output, 0-15. + pub pulse2: u8, + /// Triangle output, 0-15. + pub triangle: u8, + /// Noise output, 0-15. + pub noise: u8, + /// DMC output, 0-127. + pub dmc: u8, +} + +impl MixRecord { + /// Which channel contributed most to this sample, as an index into the + /// conventional order (0 = pulse 1 … 4 = DMC), or `None` when every channel + /// is silent. + /// + /// Compares each channel's share of **its own full scale** rather than its + /// raw value, because the raw values are not commensurable: a DMC 127 and a + /// pulse 15 are both "full scale" on different scales. + /// + /// That normalisation is **linear** — `value / max` — and deliberately does + /// NOT model the non-linear mixer, which an earlier draft of this comment + /// claimed it did. The two give different answers, since the mixer weights + /// the triangle/noise/DMC group differently from the pulses and is not + /// proportional in either. This reports which channel is working hardest + /// relative to what it can do, which is the question a user pointing at a + /// cycle is asking; attributing loudness in the final mix would be a + /// different function, and calling this one that would be a false label on + /// a correct computation. + #[must_use] + pub fn dominant(&self) -> Option { + let shares = [ + f32::from(self.pulse1) / 15.0, + f32::from(self.pulse2) / 15.0, + f32::from(self.triangle) / 15.0, + f32::from(self.noise) / 15.0, + f32::from(self.dmc) / 127.0, + ]; + let mut best = None; + let mut best_share = 0.0f32; + for (i, &s) in shares.iter().enumerate() { + if s > best_share { + best_share = s; + best = Some(i); + } + } + best + } +} + +/// One frame's worth of per-CPU-cycle mix records. +/// +/// The index **is** the cycle offset from [`Self::first_cycle`], so no per-record +/// timestamp is stored — that is what keeps the record at 16 bytes. +/// +/// Two different numbers follow from that, and the first draft of this comment +/// conflated them. An **NTSC frame** of 29,781 records is ~465 KiB; the +/// **allocation** is [`MIX_CAP`] records reserved up front, which is 576 KiB, +/// because the cap is sized from Dendy (the longest frame) rather than from +/// NTSC. The buffer is therefore always the worst case, never the typical one. +#[derive(Clone, Debug)] +pub struct MixTrace { + recs: Vec, + first_cycle: u64, + /// Set when a frame produced more cycles than [`MIX_CAP`] and records were + /// dropped. Surfaced rather than silent: a truncated trace that looks + /// complete is the failure mode this whole subsystem exists to avoid. + truncated: bool, +} + +impl MixTrace { + /// An empty trace with capacity for the worst-case region. + #[must_use] + pub fn new() -> Self { + Self { + recs: Vec::with_capacity(MIX_CAP), + first_cycle: 0, + truncated: false, + } + } + + /// Drop every record and re-anchor the trace at `first_cycle`. + pub fn clear(&mut self, first_cycle: u64) { + self.recs.clear(); + self.first_cycle = first_cycle; + self.truncated = false; + } + + /// Append one mixed cycle. Beyond [`MIX_CAP`] the record is dropped and the + /// trace is flagged [`Self::truncated`]. + pub fn push(&mut self, rec: MixRecord) { + if self.recs.len() >= MIX_CAP { + self.truncated = true; + return; + } + self.recs.push(rec); + } + + /// CPU cycle the first record corresponds to. + #[must_use] + pub const fn first_cycle(&self) -> u64 { + self.first_cycle + } + + /// Whether records were dropped for exceeding [`MIX_CAP`]. + #[must_use] + pub const fn truncated(&self) -> bool { + self.truncated + } + + /// Every record, oldest first. + #[must_use] + pub fn records(&self) -> &[MixRecord] { + &self.recs + } + + /// The record for absolute CPU `cycle`, or `None` if it is outside the + /// trace. + #[must_use] + pub fn at_cycle(&self, cycle: u64) -> Option { + let idx = usize::try_from(cycle.checked_sub(self.first_cycle)?).ok()?; + self.recs.get(idx).copied() + } +} + +impl Default for MixTrace { + fn default() -> Self { + Self::new() + } +} + +// --------------------------------------------------------------------------- +// Run-ahead carry +// --------------------------------------------------------------------------- + +/// Both audio stores, lifted out of the APU so a same-timeline restore can put +/// them back. +/// +/// **This exists because of a shipped bug, not a hypothetical one.** Pixel +/// Provenance was non-functional from v2.3.2 to v2.3.6 because run-ahead's +/// per-frame rollback cleared the provenance store *after* the visible frame was +/// produced and *before* the UI could read it — so the panel could never observe +/// a populated record, and a comment two lines above the clear asserted the +/// opposite. Audio Provenance rides the identical rollback. +/// +/// The frontend takes this before `restore_quiet` and puts it back after, which +/// leaves the restore's own reasoning completely intact: a save-state load and a +/// netplay rollback still clear, because those are genuine timeline changes. +/// Run-ahead's rollback is not — it returns to the timeline it just left. +#[derive(Debug, Default)] +pub struct AudioProvenanceStash { + pub(crate) state: Option>, +} + +impl AudioProvenanceStash { + /// Whether the store was armed when this stash was taken, so the caller can + /// skip the put-back on the common path where nothing is armed. + #[must_use] + pub const fn is_armed(&self) -> bool { + self.state.is_some() + } +} + +/// Everything audio provenance owns, behind ONE pointer. +/// +/// **Consolidated after measurement, not for tidiness.** The first shape put +/// four fields directly on `Apu` — two `Option>` plus the `u16`/`u64` +/// attribution context. That grew the struct on the hot path and the +/// `apu_throughput` bench read **+9%** on two of three workloads with the arm +/// OFF, which is the configuration the shipped frontend runs. One `Option` +/// costs eight bytes and one null test when disarmed, and everything else moves +/// behind the allocation where only an armed session pays for it. +#[derive(Clone, Debug)] +pub struct AudioProvenance { + /// Last write to each of `$4000-$4017`, with its cause. + pub reg_attrib: RegisterAttribution, + /// This frame's per-CPU-cycle mix records. + pub mix_trace: MixTrace, + /// PC of the instruction currently executing, pushed down once per + /// instruction by the core so `write_register` can attribute a write. + pub attrib_pc: u16, + /// CPU-cycle counterpart of [`Self::attrib_pc`]. + pub attrib_cycle: u64, +} + +impl AudioProvenance { + /// A freshly-armed store. + #[must_use] + pub fn new() -> Self { + Self { + reg_attrib: RegisterAttribution::new(), + mix_trace: MixTrace::new(), + attrib_pc: 0, + attrib_cycle: 0, + } + } +} + +impl Default for AudioProvenance { + fn default() -> Self { + Self::new() + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn unwritten_slots_report_none() { + let a = RegisterAttribution::new(); + for addr in REG_BASE..REG_BASE + REG_COUNT_U16 { + assert_eq!(a.get(addr), None, "{addr:#06X} should be unwritten"); + } + } + + #[test] + fn cycle_zero_is_a_real_write_not_a_sentinel() { + // The reset sequence performs writes at cycle 0. A sentinel-cycle design + // would report these as "never written". + let mut a = RegisterAttribution::new(); + a.record(0x4000, 0, 0, 0); + assert_eq!( + a.get(0x4000), + Some(RegWrite { + cycle: 0, + pc: 0, + value: 0, + origin: WriteOrigin::Instruction, + }) + ); + } + + #[test] + fn out_of_range_addresses_are_dropped_not_wrapped() { + let mut a = RegisterAttribution::new(); + a.record(0x3FFF, 0x1234, 9, 0xAA); + a.record(0x4018, 0x1234, 9, 0xBB); + a.record(0xFFFF, 0x1234, 9, 0xCC); + for addr in REG_BASE..REG_BASE + REG_COUNT_U16 { + assert_eq!(a.get(addr), None, "{addr:#06X} was written by a stray addr"); + } + assert_eq!(a.get(0x4018), None); + } + + /// A reset-driven write must NOT claim an instruction caused it. + /// + /// `Apu::reset` silences the channels via an internal + /// `write_register($4015, 0)`, which reaches the attribution table through + /// the ordinary CPU path and is therefore stamped with whatever PC was last + /// latched. Without the correction that produces a specific, confident, + /// false answer in the one register a user would look at after pressing + /// Reset. Both halves are asserted because they fail independently: the + /// origin could be right while the value went stale, or vice versa. + #[test] + fn a_reset_write_is_not_attributed_to_an_instruction() { + let mut a = RegisterAttribution::new(); + + // The CPU path runs first, exactly as `Apu::reset` causes it to. + a.record(0x4015, 0xC5F3, 1_234, 0x1F); + let before = a.get(0x4015).expect("recorded"); + assert_eq!(before.origin, WriteOrigin::Instruction); + assert_eq!(before.pc, 0xC5F3); + + // ...then the reset correction replaces the CAUSE, not the effect. + a.record_reset(0x4015, 1_234, 0x00); + let after = a.get(0x4015).expect("still recorded"); + assert_eq!( + after.origin, + WriteOrigin::Reset, + "a reset write still claims an instruction wrote it" + ); + assert_eq!( + after.value, 0x00, + "the corrected record lost the value the reset actually wrote" + ); + assert_eq!(after.cycle, 1_234, "the correction moved the write in time"); + + // A neighbouring slot is untouched -- the correction is not a wipe. + assert!(a.get(0x4014).is_none()); + } + + #[test] + fn last_write_wins_per_address_and_addresses_are_independent() { + let mut a = RegisterAttribution::new(); + a.record(0x4003, 0x8000, 10, 0x11); + a.record(0x4003, 0x8100, 20, 0x22); + a.record(0x4007, 0x8200, 30, 0x33); + assert_eq!( + a.get(0x4003).map(|w| (w.pc, w.cycle, w.value)), + Some((0x8100, 20, 0x22)) + ); + assert_eq!( + a.get(0x4007).map(|w| (w.pc, w.cycle, w.value)), + Some((0x8200, 30, 0x33)) + ); + } + + #[test] + fn mix_trace_index_is_the_cycle_offset() { + let mut t = MixTrace::new(); + t.clear(1_000); + for i in 0..4u8 { + t.push(MixRecord { + pulse1: i, + ..MixRecord::default() + }); + } + assert_eq!(t.at_cycle(1_000).map(|r| r.pulse1), Some(0)); + assert_eq!(t.at_cycle(1_003).map(|r| r.pulse1), Some(3)); + assert_eq!(t.at_cycle(999), None, "before the anchor"); + assert_eq!(t.at_cycle(1_004), None, "past the end"); + } + + #[test] + fn truncation_is_reported_rather_than_silent() { + let mut t = MixTrace::new(); + t.clear(0); + for _ in 0..MIX_CAP { + t.push(MixRecord::default()); + } + assert!(!t.truncated(), "exactly at capacity is not truncation"); + t.push(MixRecord::default()); + assert!(t.truncated(), "over capacity must be visible to the caller"); + assert_eq!(t.records().len(), MIX_CAP); + } + + #[test] + fn mix_cap_covers_the_worst_case_region() { + // Dendy, not NTSC, is the worst case: 1_773_448 / 50.007 = 35,464. + // Sizing from the NTSC number would truncate 16% of every Dendy frame. + // Integer arithmetic: a float cast here would trip the truncation + // lint that this crate denies, and ceil-divide is the exact operation + // the bound needs anyway. + let dendy_cycles_per_frame = (1_773_448_000_usize).div_ceil(50_007); + assert!( + MIX_CAP >= dendy_cycles_per_frame, + "MIX_CAP {MIX_CAP} < Dendy {dendy_cycles_per_frame}" + ); + } + + #[test] + fn dominant_compares_normalised_share_not_raw_value() { + // DMC 100/127 (0.787) beats pulse 15/15? No — pulse is 1.0. The point is + // that raw magnitude would pick the DMC, and share picks the pulse. + let r = MixRecord { + pulse1: 15, + dmc: 100, + ..MixRecord::default() + }; + assert_eq!(r.dominant(), Some(0), "pulse at full scale must win"); + + let r = MixRecord { + pulse1: 8, + dmc: 100, + ..MixRecord::default() + }; + assert_eq!(r.dominant(), Some(4), "DMC 0.787 beats pulse 0.533"); + + assert_eq!( + MixRecord::default().dominant(), + None, + "silence has no winner" + ); + } + + #[test] + fn a_stash_reports_unarmed_when_empty() { + assert!(!AudioProvenanceStash::default().is_armed()); + } +} diff --git a/crates/rustynes-core/Cargo.toml b/crates/rustynes-core/Cargo.toml index 519338c7..2d1f62af 100644 --- a/crates/rustynes-core/Cargo.toml +++ b/crates/rustynes-core/Cargo.toml @@ -53,7 +53,7 @@ cpu-instr-cycle-trace = ["rustynes-cpu/cpu-instr-cycle-trace"] # determinism contract; the frontend enables it. The hooks are output-only (they may # stop the frame early or record state) and never mutate emulation, so even with the # feature ON the persistent timeline is unchanged. -debug-hooks = ["std", "rustynes-ppu/debug-hooks"] +debug-hooks = ["std", "rustynes-ppu/debug-hooks", "rustynes-apu/debug-hooks"] # v1.2.0 beta.2 (Workstream C3) — HD-pack tile-source telemetry. Forwards to # `rustynes-ppu/hd-pack`, which gates the per-pixel `HdTileSource` export inside # `emit_pixel`. Off by default so the shipped / wasm / no_std builds are diff --git a/crates/rustynes-core/src/bus.rs b/crates/rustynes-core/src/bus.rs index bbf5a495..52ad8cc3 100644 --- a/crates/rustynes-core/src/bus.rs +++ b/crates/rustynes-core/src/bus.rs @@ -4383,10 +4383,25 @@ impl Bus for LockstepBus { // moved on to whichever instruction is being halted. #[cfg(feature = "debug-hooks")] self.ppu.latch_dma_attrib_context(); + // v2.3.7 "Overtone" — `$4014` sits inside the `$4000-$4017` + // window the audio-provenance table reserves a slot for, but the + // arm below routes only `$4000-$4013 | $4015 | $4017` to + // `Apu::write_register`, where attribution is recorded. Record it + // here so the reserved slot is actually populated; nothing is + // dispatched to the APU, so the DMA behaviour is unchanged. + #[cfg(feature = "debug-hooks")] + self.apu + .record_bus_handled_register_write(REG_OAM_DMA, value); self.dma_pending = Some(value); } 0x4000..=0x4013 | 0x4015 | 0x4017 => self.apu.write_register(addr, value), 0x4016 => { + // v2.3.7 "Overtone" — same as `$4014` above: inside the + // provenance window, never routed to `Apu::write_register`, so + // attribute it here. The strobe itself is still buffered and + // committed by the code below; this only records the cause. + #[cfg(feature = "debug-hooks")] + self.apu.record_bus_handled_register_write(0x4016, value); // Session-24 / Phase 3 (Controller Strobing): the // controllers' OUT pins are only updated at the start // of M2-low (PUT) cycles. Buffer the write and diff --git a/crates/rustynes-core/src/nes.rs b/crates/rustynes-core/src/nes.rs index 2483e4a8..0b2fda5b 100644 --- a/crates/rustynes-core/src/nes.rs +++ b/crates/rustynes-core/src/nes.rs @@ -504,6 +504,9 @@ impl Nes { { self.bus.ppu.clear_write_attribution(); self.bus.ppu.clear_pixel_provenance(); + // v2.3.7 — same for audio: a cold boot ends the history the + // register attribution describes. + self.bus.apu.clear_audio_provenance_history(); } } @@ -520,6 +523,12 @@ impl Nes { // VBL detection or DMA-stall heavy frames before declaring "stuck". const MAX_CYCLES_PER_FRAME: u64 = 150_000; let start = self.bus.cycle(); + // v2.3.7 "Overtone" — anchor this frame's mix trace. The trace is + // per-frame (the index IS the cycle offset from here); the REGISTER + // attribution deliberately is not, because "which instruction last wrote + // $4003" has an answer that legitimately predates this frame. + #[cfg(feature = "debug-hooks")] + self.bus.apu.begin_audio_provenance_frame(start); // T-110-C3 — the event viewer shows one frame; reset the log per frame. #[cfg(feature = "debug-hooks")] if self.bus.event_logging() { @@ -602,6 +611,15 @@ impl Nes { self.bus .ppu .set_attrib_context(self.cpu.pc, self.cpu.cycles); + // v2.3.7 "Overtone" — the same push-down for audio, so + // `Apu::write_register` can attribute a `$4000-$4017` write + // without `rustynes-cpu` knowing the feature exists. Same + // reasoning as the PPU line above: two unconditional stores are + // cheaper than testing an arm behind a `Box` across a crate + // boundary, in a block that already scans breakpoints. + self.bus + .apu + .set_attrib_context(self.cpu.pc, self.cpu.cycles); // T-110-C2 — cycle trace: record the about-to-execute // instruction's CPU state (ring-capped, oldest dropped). if self.trace_enabled { @@ -672,6 +690,10 @@ impl Nes { self.bus .ppu .set_attrib_context(self.cpu.pc, self.cpu.cycles); + #[cfg(feature = "debug-hooks")] + self.bus + .apu + .set_attrib_context(self.cpu.pc, self.cpu.cycles); self.cpu.step(&mut self.bus) } @@ -899,6 +921,62 @@ impl Nes { self.bus.ppu.pixel_provenance() } + /// Arm or disarm **audio** provenance (v2.3.7 "Overtone"). + /// + /// Off by default. Arming allocates the per-register write attribution and + /// the per-CPU-cycle mix trace; disarming frees both. Output-only — nothing + /// recorded is read back into synthesis or carried in the save state, so the + /// deterministic audio contract is unaffected either way. + #[cfg(feature = "debug-hooks")] + pub fn set_audio_provenance(&mut self, enabled: bool) { + self.bus.apu.set_audio_provenance(enabled); + } + + /// Whether audio provenance is armed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub const fn audio_provenance_armed(&self) -> bool { + self.bus.apu.audio_provenance_armed() + } + + /// The per-register write attribution — which instruction last wrote each of + /// `$4000-$4017` — or `None` when disarmed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn register_attribution(&self) -> Option<&rustynes_apu::provenance::RegisterAttribution> { + self.bus.apu.register_attribution() + } + + /// This frame's per-CPU-cycle mix trace, or `None` when disarmed. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn mix_trace(&self) -> Option<&rustynes_apu::provenance::MixTrace> { + self.bus.apu.mix_trace() + } + + /// Lift the audio provenance stores out for a same-timeline restore. + /// + /// The audio counterpart of [`Self::take_provenance`], and it exists for the + /// identical reason: run-ahead's rollback runs AFTER the visible frame is + /// produced and BEFORE the frontend releases the emulator lock, so a store + /// the restore clears can never be observed by the UI. That is exactly how + /// Pixel Provenance shipped non-functional from v2.3.2 to v2.3.6. Take + /// before the restore, [`Self::put_audio_provenance`] after. + /// + /// Save-state loads and netplay rollback still clear, unchanged — those are + /// genuine timeline changes. Run-ahead's rollback is not. + #[cfg(feature = "debug-hooks")] + #[must_use] + pub fn take_audio_provenance(&mut self) -> rustynes_apu::provenance::AudioProvenanceStash { + self.bus.apu.take_audio_provenance() + } + + /// Put back stores taken by [`Self::take_audio_provenance`]. + #[cfg(feature = "debug-hooks")] + pub fn put_audio_provenance(&mut self, stash: rustynes_apu::provenance::AudioProvenanceStash) { + self.bus.apu.put_audio_provenance(stash); + } + /// v2.3.6 — move both provenance stores out, leaving them unarmed. /// /// For a host that performs a **same-timeline** restore whose result the user @@ -2062,6 +2140,21 @@ impl Nes { { self.bus.ppu.clear_write_attribution(); self.bus.ppu.clear_pixel_provenance(); + // v2.3.7 — the audio register attribution is the same kind of claim + // about the same replaced timeline: a restored state's APU registers + // were not written by any instruction this session executed, so + // keeping their PCs would report a timeline that no longer exists. + // + // This was MISSING when audio provenance first landed, while + // `docs/audio-provenance.md` already asserted that "save-state loads + // and netplay rollback still clear" — prose describing behaviour the + // code did not have, which is the exact failure that let Pixel + // Provenance ship broken for four releases. Caught in review. + // + // Harmless for run-ahead: `RunAhead::finish` TAKES the store before + // `restore_quiet` and puts it back after, so `audio_prov` is `None` + // here and this call is a no-op on that path. + self.bus.apu.clear_audio_provenance_history(); } Ok(()) } @@ -4196,6 +4289,75 @@ mod tests { ); } + /// v2.3.7: `$4014` and `$4016` must actually be attributed. + /// + /// Both sit inside the `$4000-$4017` window the audio-provenance table + /// reserves slots for, and both are handled entirely on the bus — `Bus::write` + /// routes only `$4000-$4013 | $4015 | $4017` to `Apu::write_register`, which + /// is where attribution was recorded. So the two reserved slots could never + /// be filled, while `docs/audio-provenance.md` and the `REG_COUNT` doc + /// comment both stated they were "tracked anyway". + /// + /// Caught by the Antigravity reviewer on PR #404. This test fails without + /// `Apu::record_bus_handled_register_write` being called from both bus arms: + /// remove either call and the corresponding `get()` returns `None`. + #[cfg(feature = "debug-hooks")] + #[test] + fn bus_handled_apu_window_writes_are_attributed() { + // `Bus::write` is the ordinary CPU write path both addresses travel. + use rustynes_cpu::Bus as _; + + let mut nes = Nes::from_rom(&synth_nrom(16, 8)).expect("nrom builds"); + nes.set_audio_provenance(true); + assert!(nes.audio_provenance_armed(), "premise: armed"); + + // Pin a known attribution context, then write both bus-handled + // addresses through the ordinary CPU write path. + nes.bus.apu.set_attrib_context(0xC123, 4_242); + nes.bus.write(0x4014, 0x02); // OAM DMA page + nes.bus.write(0x4016, 0x01); // controller strobe + + let attrib = nes + .bus + .apu + .register_attribution() + .expect("armed, so the table exists"); + + let dma = attrib + .get(0x4014) + .expect("$4014 must be attributed — it is inside the reserved window"); + assert_eq!(dma.pc, 0xC123, "$4014 attributed to the wrong instruction"); + assert_eq!(dma.value, 0x02, "$4014 recorded the wrong value"); + + let strobe = attrib + .get(0x4016) + .expect("$4016 must be attributed — it is inside the reserved window"); + assert_eq!( + strobe.pc, 0xC123, + "$4016 attributed to the wrong instruction" + ); + assert_eq!(strobe.value, 0x01, "$4016 recorded the wrong value"); + + // A genuine APU register still works — the new path is additive, not a + // replacement for the one inside `write_register`. + nes.bus.write(0x4015, 0x0F); + assert_eq!( + attrib_value(&nes, 0x4015), + Some(0x0F), + "the normal write_register attribution path must be unaffected" + ); + } + + /// Small helper so the assertion above reads as one line. + #[cfg(feature = "debug-hooks")] + fn attrib_value(nes: &Nes, addr: u16) -> Option { + nes.bus + .apu + .register_attribution() + .and_then(|a| a.get(addr)) + .map(|w| w.value) + } + #[test] fn nsf_song_apis_are_inert_on_a_cartridge() { let mut nes = Nes::from_rom(&synth_nrom(16, 8)).expect("nrom builds"); diff --git a/crates/rustynes-frontend/src/debugger/audio_provenance_panel.rs b/crates/rustynes-frontend/src/debugger/audio_provenance_panel.rs new file mode 100644 index 00000000..d38b2080 --- /dev/null +++ b/crates/rustynes-frontend/src/debugger/audio_provenance_panel.rs @@ -0,0 +1,355 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +//! Audio provenance inspector (v2.3.7 "Overtone"). +//! +//! Pick a moment in the frame and read why it sounds like that: what each +//! channel was putting out, which one dominated the mix, and — for every APU +//! register — the value it holds, the CPU cycle it was written on, and **the +//! instruction that wrote it**. +//! +//! # Relationship to the other audio panels +//! +//! Deliberately not a replacement for either. The Audio Scope plots *what the +//! waveform looks like*; the Audio Mixer sets *how loud each channel is*. This +//! answers *why* — which neither can, because neither has the link from a +//! sample back to the instruction responsible for it. +//! +//! # What it does not claim +//! +//! The trace is per **CPU cycle**, which is the cadence the mix is actually +//! computed at. Output samples come out of a band-limited decimator at ~40.6 +//! CPU cycles each, and an output sample is a weighted sum of transitions across +//! the filter kernel — not a copy of one instant. So this panel reports the +//! cycle window, and says so, rather than pretending a sample has a single +//! originating cycle. + +use crate::debugger::source_map::SourceMap; +use rustynes_core::Nes; +use rustynes_core::rustynes_apu::provenance::{REG_BASE, REG_COUNT_U16}; + +/// The APU register names, indexed from `$4000`. +/// +/// `$4014` and `$4016` are inside the traced range and are not APU registers; +/// they are labelled for what they are rather than blanked, so a user who sees +/// a write to one is told why it is there. +const REG_NAMES: [&str; 0x18] = [ + "$4000 Pulse1 ctrl", + "$4001 Pulse1 sweep", + "$4002 Pulse1 timer lo", + "$4003 Pulse1 timer hi", + "$4004 Pulse2 ctrl", + "$4005 Pulse2 sweep", + "$4006 Pulse2 timer lo", + "$4007 Pulse2 timer hi", + "$4008 Tri linear", + "$4009 (unused)", + "$400A Tri timer lo", + "$400B Tri timer hi", + "$400C Noise ctrl", + "$400D (unused)", + "$400E Noise period", + "$400F Noise length", + "$4010 DMC ctrl", + "$4011 DMC DAC", + "$4012 DMC addr", + "$4013 DMC length", + "$4014 OAM DMA (not APU)", + "$4015 Status", + "$4016 Controller (not APU)", + "$4017 Frame counter", +]; + +/// Channel labels in the order [`rustynes_apu::provenance::MixRecord::dominant`] +/// indexes them. +const CHANNELS: [&str; 5] = ["Pulse 1", "Pulse 2", "Triangle", "Noise", "DMC"]; + +/// Side-band effects a write carries beyond the obvious one. +/// +/// **This is the research obligation the plan recorded, made visible.** A naive +/// reading of "last write to `$4003`" says "the period changed" — but that one +/// write ALSO loads the length counter, resets the duty sequencer, and restarts +/// the envelope. A provenance tool that names the right instruction and then +/// describes the wrong effect is precisely the failure this project keeps +/// paying for, so the extra effects are spelled out at the point of use. +/// +/// Confirmed against this emulator's own implementation rather than from memory: +/// `Pulse::write_timer_hi`, `Triangle::write_linear`, `Apu::write_status`, and +/// the `$4017` alignment comment in `Apu::write_register`. +const fn side_effects(idx: usize) -> Option<&'static str> { + match idx { + // $4003 / $4007 + 0x03 | 0x07 => Some( + "also loads the length counter, resets the duty sequencer, and restarts the envelope", + ), + // $4008 + 0x08 => { + Some("length-counter halt is DEFERRED — applied after the same-cycle half-frame clock") + } + // $400B + 0x0B => Some("also loads the length counter and sets the linear-counter reload flag"), + // $400F + 0x0F => Some("also loads the length counter and restarts the envelope"), + // $4015 + 0x15 => Some( + "enables/disables length counters; the DMC enable is latched and applied with a delay", + ), + // $4017 + 0x17 => Some("effects land 3 CPU cycles after the write on an APU clock, 4 otherwise"), + _ => None, + } +} + +/// Panel state: the pinned cycle, and nothing else the core already knows. +/// +/// **No mirror of the core's armed flag.** The v2.3.6 pixel panel kept one and +/// edge-detected on it, which desynced permanently the moment a ROM load +/// installed a fresh `Nes`: the checkbox stayed ticked over an unarmed core, +/// with no way back but unticking and re-ticking. The core is re-read every +/// frame here instead. +#[derive(Default)] +pub struct AudioProvenancePanelState { + /// Offset into the current frame's mix trace, in CPU cycles. + pin: usize, + /// Follow the newest recorded cycle instead of holding `pin`. + follow: bool, +} + +impl AudioProvenancePanelState { + /// Discard the ROM-bound half of this panel's state. + /// + /// Registered with [`super::DebuggerOverlay::clear_rom_bound_analysis`], + /// whose doc comment says the next ROM-bound panel is "one line away from + /// being correct instead of one omission away from being wrong". This panel + /// was that omission until it was caught, which is the third instance of + /// the same seam after the Latency Oracle and Pixel Provenance. + /// + /// `pin` is cleared: a cycle offset chosen while watching one game names + /// nothing in particular in another. It cannot panic if left stale — the + /// render clamps it to the live record count every frame — so this is about + /// the panel not silently presenting a cycle the user never picked. + /// + /// `follow` is deliberately KEPT. It is a display preference, not a + /// measurement: "show me the newest cycle" means exactly the same thing on + /// the next ROM, and resetting it would make a ROM load quietly undo a + /// setting the user chose. Clearing state wholesale is the easy call and + /// the wrong one; the hook exists to discard results, not preferences. + pub(super) const fn clear(&mut self) { + self.pin = 0; + } +} + +/// Render the inspector. +pub fn show( + ctx: &egui::Context, + detached: &mut std::collections::HashSet<&'static str>, + open: &mut bool, + state: &mut AudioProvenancePanelState, + nes: &mut Nes, + source_map: &SourceMap, +) { + // The CORE is the source of truth for the arm, re-read every frame, for the + // reason `AudioProvenancePanelState` documents. + let armed = nes.audio_provenance_armed(); + let mut want_armed = armed; + + super::detachable_window( + ctx, + detached, + "audio_provenance", + "Audio Provenance", + super::WindowCfg { + default_size: Some([520.0, 600.0]), + ..Default::default() + }, + open, + |ui| { + ui.horizontal(|ui| { + ui.checkbox(&mut want_armed, "Enable"); + ui.separator(); + ui.checkbox(&mut state.follow, "Follow newest"); + }); + ui.label( + egui::RichText::new( + "Records the channel outputs mixed on every CPU cycle, and which \ + instruction last wrote each APU register.", + ) + .small() + .weak(), + ); + ui.separator(); + + if !armed { + ui.label("Not armed — tick Enable, then let a frame run."); + return; + } + + let Some(trace) = nes.mix_trace() else { + ui.label("Armed, but the trace is not allocated yet."); + return; + }; + let recs = trace.records(); + if recs.is_empty() { + // Distinct from "not armed" on purpose. A panel whose only failure + // mode is a confident blank report cannot be trusted even once it + // works — the lesson the pixel inspector cost four releases. + ui.label("Armed, but no cycles recorded for this frame yet."); + return; + } + + if trace.truncated() { + ui.colored_label( + egui::Color32::from_rgb(0xE0, 0xA0, 0x30), + "Trace truncated: this frame produced more cycles than the buffer holds.", + ); + } + + if state.follow { + state.pin = recs.len() - 1; + } + state.pin = state.pin.min(recs.len() - 1); + + ui.horizontal(|ui| { + ui.label("Cycle offset:"); + ui.add( + egui::Slider::new(&mut state.pin, 0..=recs.len() - 1) + .clamping(egui::SliderClamping::Always), + ); + }); + + let rec = recs[state.pin]; + let abs_cycle = trace.first_cycle() + state.pin as u64; + ui.label(format!( + "CPU cycle {abs_cycle} ({} of {} this frame)", + state.pin + 1, + recs.len() + )); + ui.label( + egui::RichText::new( + "One output sample spans ~40.6 of these cycles; a sample is a \ + weighted sum across the filter kernel, not a copy of one cycle.", + ) + .small() + .weak(), + ); + ui.separator(); + + // --- the mix at that cycle --- + let dominant = rec.dominant(); + egui::Grid::new("audio_prov_mix") + .num_columns(3) + .striped(true) + .show(ui, |ui| { + ui.label(egui::RichText::new("Channel").strong()); + ui.label(egui::RichText::new("Output").strong()); + ui.label(egui::RichText::new("Share").strong()); + ui.end_row(); + + let vals = [rec.pulse1, rec.pulse2, rec.triangle, rec.noise, rec.dmc]; + let fulls = [15.0f32, 15.0, 15.0, 15.0, 127.0]; + for (i, name) in CHANNELS.iter().enumerate() { + let lead = dominant == Some(i); + let label = if lead { + egui::RichText::new(*name).strong() + } else { + egui::RichText::new(*name) + }; + ui.label(label); + ui.label(format!("{}", vals[i])); + ui.label(format!("{:.0}%", f32::from(vals[i]) / fulls[i] * 100.0)); + ui.end_row(); + } + }); + ui.label(format!( + "Mixed: {:.5} Expansion: {:.5}", + rec.mixed, rec.external + )); + ui.label(dominant.map_or_else( + || "Dominant: none — every channel silent".to_owned(), + |i| format!("Dominant: {}", CHANNELS[i]), + )); + + ui.separator(); + ui.label(egui::RichText::new("Register writes").strong()); + + // --- who wrote each register --- + let Some(attrib) = nes.register_attribution() else { + ui.label("No register attribution."); + return; + }; + egui::ScrollArea::vertical() + .max_height(240.0) + .show(ui, |ui| { + egui::Grid::new("audio_prov_regs") + .num_columns(4) + .striped(true) + .show(ui, |ui| { + ui.label(egui::RichText::new("Register").strong()); + ui.label(egui::RichText::new("Value").strong()); + ui.label(egui::RichText::new("Cycle").strong()); + ui.label(egui::RichText::new("Written by").strong()); + ui.end_row(); + + // Iterate the ADDRESS, not an index needing a cast. + // The previous form was `0x4000 + + // u16::try_from(i).unwrap_or(0)`, whose fallback + // would silently fold an out-of-range index onto + // `$4000` -- a wrong row rather than an absent one, + // in a panel whose entire job is not to answer + // wrongly. Zipping the address range against the + // name table makes the bad case unrepresentable + // instead of merely unlikely, and avoids an `as` + // cast the workspace lints deny. (Review suggestion, + // taken further than proposed.) + for (off, name) in (0..REG_COUNT_U16).zip(REG_NAMES.iter()) { + let i = usize::from(off); + let addr = REG_BASE + off; + let Some(w) = attrib.get(addr) else { + continue; + }; + ui.label(*name); + ui.label(format!("{:#04X}", w.value)); + ui.label(format!("{}", w.cycle)); + match w.origin { + rustynes_core::rustynes_apu::provenance::WriteOrigin::Instruction => { + ui.label(source_map.annotation(w.pc).map_or_else( + || format!("{:#06X}", w.pc), + |s| format!("{:#06X} {s}", w.pc), + )); + } + // No instruction caused this one, so no PC is + // printed. Naming a plausible address here would + // be the tool lying in exactly the register it is + // supposed to explain. + rustynes_core::rustynes_apu::provenance::WriteOrigin::Reset => { + ui.label("APU reset (not an instruction)"); + } + } + ui.end_row(); + + if let Some(extra) = side_effects(i) { + ui.label(""); + ui.label(""); + ui.label(""); + ui.label(egui::RichText::new(extra).small().weak()); + ui.end_row(); + } + } + }); + }); + ui.label( + egui::RichText::new( + "Registers with no row have not been written since audio provenance was \ + enabled. Arming allocates a fresh table, so writes made before you ticked \ + Enable are not shown.", + ) + .small() + .weak(), + ); + }, + ); + + // Applied AFTER the body renders, so the core sees one arming change per + // frame and the panel never reads a store it just freed. + if want_armed != armed { + nes.set_audio_provenance(want_armed); + } +} diff --git a/crates/rustynes-frontend/src/debugger/mod.rs b/crates/rustynes-frontend/src/debugger/mod.rs index 8bc725cf..d363179b 100644 --- a/crates/rustynes-frontend/src/debugger/mod.rs +++ b/crates/rustynes-frontend/src/debugger/mod.rs @@ -147,6 +147,7 @@ mod nsf_panel; mod oam_panel; mod replay_panel; // v2.8.0 Phase 0 — frame-pacing / audio-health instrumentation panel. +mod audio_provenance_panel; mod perf_panel; mod ppu_panel; mod provenance_panel; @@ -222,6 +223,10 @@ pub enum ToolPanel { /// The variant is unconditional so the menu IA + dispatch match stay /// exhaustive; the panel and its open path are `debug-hooks`-gated. PixelProvenance, + /// v2.3.7 "Overtone" — the audio provenance inspector: the causal chain from + /// a moment in the mix back to the channels and the writing instruction. + /// Unconditional variant for the same reason as [`Self::PixelProvenance`]. + AudioProvenance, } /// A chip-inspection panel surfaced from the Debug menu (v1.0.0). @@ -693,6 +698,8 @@ pub struct DebuggerOverlay { writes_locked: bool, /// v2.3.2 "Lucid" — pixel provenance inspector. show_provenance: bool, + show_audio_provenance: bool, + audio_provenance_ui: audio_provenance_panel::AudioProvenancePanelState, /// "Input Display" panel open flag (v1.7.0 "Forge" beta.5, #51; née the /// v1.5.0 A1 Input Miniatures overlay). show_input_display: bool, @@ -961,6 +968,8 @@ impl DebuggerOverlay { show_atlas: false, writes_locked: false, show_provenance: false, + show_audio_provenance: false, + audio_provenance_ui: audio_provenance_panel::AudioProvenancePanelState::default(), show_input_display: false, #[cfg(all(not(target_arch = "wasm32"), feature = "hd-pack"))] show_hd_pixel: false, @@ -1154,6 +1163,9 @@ impl DebuggerOverlay { pub fn clear_rom_bound_analysis(&mut self) { self.clear_latency_report(); self.atlas_ui.clear(); + // v2.3.7 — Audio Provenance. Registered here rather than given its own + // per-panel clear, which is the whole point of this hook existing. + self.audio_provenance_ui.clear(); } /// Returns `true` when the overlay is currently visible. The render @@ -1531,6 +1543,7 @@ impl DebuggerOverlay { ToolPanel::LatencyOracle => self.show_latency = true, ToolPanel::RamAtlas => self.show_atlas = true, ToolPanel::PixelProvenance => self.show_provenance = true, + ToolPanel::AudioProvenance => self.show_audio_provenance = true, ToolPanel::InputDisplay => self.show_input_display = true, ToolPanel::Replay => self.show_replay = true, ToolPanel::BasicBot => self.show_basic_bot = true, @@ -1814,6 +1827,7 @@ impl DebuggerOverlay { || self.show_game_db || self.show_rom_info || self.show_provenance + || self.show_audio_provenance || self.show_latency || self.show_atlas } @@ -2504,6 +2518,21 @@ impl DebuggerOverlay { &self.source_map, ); } + if self.show_audio_provenance + && let Some(nes) = nes.as_deref_mut() + { + // v2.3.7 "Overtone" — why does this moment sound like that. Takes + // `&mut Nes` only to arm / disarm the output-only stores; the report + // itself is read-only. + audio_provenance_panel::show( + ctx, + &mut self.detached_panels, + &mut self.show_audio_provenance, + &mut self.audio_provenance_ui, + nes, + &self.source_map, + ); + } if self.show_rom_info && let Some(nes) = nes.as_deref() { diff --git a/crates/rustynes-frontend/src/runahead.rs b/crates/rustynes-frontend/src/runahead.rs index e001eec2..dfb55300 100644 --- a/crates/rustynes-frontend/src/runahead.rs +++ b/crates/rustynes-frontend/src/runahead.rs @@ -101,11 +101,20 @@ impl RunAhead { /// guarantee netplay rollback relies on). pub fn finish(&mut self, nes: &mut Nes) { let stash = nes.take_provenance(); + // v2.3.7 "Overtone" — the audio stores ride the SAME rollback and would + // be wiped the same way. Carried around it for the identical reason, + // and added in the same change as the feature rather than after a user + // reports an empty panel: that is what the video side cost, four + // releases of a marquee feature that could never show anything. + let audio_stash = nes.take_audio_provenance(); nes.restore_quiet(&self.snap_buf) .expect("run-ahead snapshot round-trips on the same instance"); if stash.is_armed() { nes.put_provenance(stash); } + if audio_stash.is_armed() { + nes.put_audio_provenance(audio_stash); + } nes.set_rewind_capture(true); } @@ -375,6 +384,86 @@ mod tests { } } + /// A frame's worth of mixed cycles, floored well under the NTSC 29,781 so + /// the assertion is about "a real frame ran" rather than an exact count. + /// + /// Deliberately NOT `> 0`: the APU's 8-cycle reset sequence alone produces + /// eight records, so a non-emptiness check passes on a run that emulated + /// nothing at all. That is the vacuous-assertion shape this project keeps + /// paying for. + const MIN_FRAME_MIXES: usize = 20_000; + + /// CONTROL for [`runahead_preserves_audio_provenance`]: without run-ahead, a + /// plain run leaves a populated mix trace. If this fails, the run-ahead test + /// below proves nothing — the store would be empty for a reason unrelated to + /// the rollback. + /// + /// Runs three frames for the same reason the pixel-provenance control does: + /// a single `run_frame` immediately after `from_rom` can legitimately + /// advance **zero** cycles, because the PPU starts at a frame boundary. + /// Writing this with one frame is how I first "disproved" a feature that was + /// working correctly. + #[test] + fn plain_run_leaves_audio_provenance_populated() { + let bytes = rom("assorted/flowing_palette.nes"); + let mut nes = Nes::from_rom(&bytes).expect("rom parses"); + nes.set_audio_provenance(true); + let mut discard = vec![0.0f32; 8192]; + + for _ in 0..3u32 { + nes.run_frame(); + let _ = nes.drain_audio_into(&mut discard); + } + + let trace = nes.mix_trace().expect("armed, so the trace is allocated"); + assert!( + trace.records().len() >= MIN_FRAME_MIXES, + "control failed: a plain run recorded {} mixed cycles, so the marker \ + used by `runahead_preserves_audio_provenance` is not valid", + trace.records().len() + ); + } + + /// **The test whose absence cost the video side four releases.** + /// + /// Pixel Provenance shipped non-functional from v2.3.2 to v2.3.6 because + /// run-ahead's rollback cleared the store after the visible frame was + /// produced and before the UI could take the lock. Audio provenance rides + /// the identical rollback, so it gets the identical test — driving the real + /// produce path at `run_ahead = 1`, the default, and looking at the first + /// moment the UI actually could. + #[test] + fn runahead_preserves_audio_provenance() { + let bytes = rom("assorted/flowing_palette.nes"); + let mut nes = Nes::from_rom(&bytes).expect("rom parses"); + nes.enable_rewind(); + nes.set_audio_provenance(true); + + let mut ra = RunAhead::default(); + let mut discard = vec![0.0f32; 8192]; + + for frame in 0..3u32 { + ra.run_frame_ahead(&mut nes, 1); + // The frontend harvests the visible framebuffer + audio here. + let _ = nes.drain_audio_into(&mut discard); + ra.finish(&mut nes); + + // ...and only THEN releases the lock, so this is the first moment + // the UI could look. + assert!( + nes.audio_provenance_armed(), + "frame {frame}: the rollback disarmed audio provenance" + ); + let trace = nes.mix_trace().expect("armed, so the trace is allocated"); + assert!( + trace.records().len() >= MIN_FRAME_MIXES, + "frame {frame}: run-ahead's rollback wiped the visible frame's mix \ + trace ({} records) — the inspector panel can never see a record", + trace.records().len() + ); + } + } + /// Arming must survive the rollback too — a wiped-and-disarmed store would /// make the panel say "enable it, then run a frame" forever. #[test] diff --git a/crates/rustynes-frontend/src/ui_shell.rs b/crates/rustynes-frontend/src/ui_shell.rs index 8562d103..837b41cb 100644 --- a/crates/rustynes-frontend/src/ui_shell.rs +++ b/crates/rustynes-frontend/src/ui_shell.rs @@ -1394,6 +1394,20 @@ impl UiShell { out.action = Some(MenuAction::OpenPanel(ToolPanel::PixelProvenance)); ui.close(); } + // v2.3.7 "Overtone" — the audio counterpart: why does + // this moment sound like that. Sits beside Pixel + // Provenance because they answer the same question about + // the two halves of the output. + if ui + .add_enabled( + rom, + egui::Button::new(ic(glyph::VOLUME_HIGH, "Audio Provenance")), + ) + .clicked() + { + out.action = Some(MenuAction::OpenPanel(ToolPanel::AudioProvenance)); + ui.close(); + } // v2.3.6 workstream C — the RAM Atlas: classify every // byte of work RAM by behaviour, then verify a candidate // by perturbing it. Sits with the other output-only diff --git a/crates/rustynes-test-harness/tests/snapshot_schema_audit.rs b/crates/rustynes-test-harness/tests/snapshot_schema_audit.rs index c83e2875..6ac21328 100644 --- a/crates/rustynes-test-harness/tests/snapshot_schema_audit.rs +++ b/crates/rustynes-test-harness/tests/snapshot_schema_audit.rs @@ -314,6 +314,20 @@ const CHIPS: &[Chip] = &[ for the UI oscilloscope; documented as never read back into the mixer, the \ IRQ path, or any determinism-relevant state", ), + ( + "audio_prov", + "output-only: v2.3.7 audio provenance -- per-register write attribution, the \ + per-CPU-cycle mix trace, and the PC/cycle context feeding them, all behind one \ + `Option>`. Never read by emulation. Deliberately NOT serialized for the \ + same reason the PPU's `write_attrib` is not -- a restored state's registers were \ + not written by any instruction this session ran, so carrying PCs across a restore \ + would report a timeline that no longer exists. The mix trace is per-FRAME by \ + construction (re-anchored by `begin_audio_provenance_frame`) and the context is \ + re-pushed before every instruction, so neither has anything a save state could \ + meaningfully carry. \ + CONSOLIDATED from four inline fields after `apu_throughput` measured +9% on the \ + DISARMED path with the state spread across the `Apu` struct", + ), ], known_gaps: &[], }, diff --git a/docs/audio-provenance.md b/docs/audio-provenance.md new file mode 100644 index 00000000..ea736a3a --- /dev/null +++ b/docs/audio-provenance.md @@ -0,0 +1,309 @@ +# Audio provenance + +**Status:** implemented in v2.3.7 "Overtone". Output-only, default-off, and not +part of the save state — the deterministic audio contract is unaffected whether +it is armed or not. + +The APU counterpart of [pixel provenance](pixel-provenance.md), and deliberately +the same shape: a **register-attribution** half that answers *"what wrote this, +and from which instruction"*, and a **mix trace** that answers *"what were the +channels actually doing"*. + +## What the feature answers + +Pick a moment in the frame and read the causal chain: + +- the mixed value handed to the band-limited decimator, and the expansion-audio + contribution folded into it; +- what each of the five channels was putting out, as a share of its own full + scale; +- which channel **dominated**; +- for every APU register, the value it holds, the CPU cycle it was written on, + and **the instruction that wrote it** — symbolised through the source map when + one is loaded. + +## Why this is not just wiring up existing panels + +Every ingredient but one already shipped. `audio_scope.rs` plots the per-channel +waveforms. `audio_mixer.rs` exposes per-channel gain. `Apu::pulse1_out()` and its +siblings expose live channel outputs. The Trace Logger has PC and cycle. The +Event Viewer already records `$4000-$4017` writes as `EventKind::ApuWrite`. + +What did not exist anywhere is the **link between a sample and the instruction +that caused it**. `EventRec` carries `kind / scanline / dot / addr / value` — no +PC, no CPU cycle, and it is scanline-oriented rather than sample-oriented. So the +event log is the interception *point* this feature reuses; it is not the record. + +## Cadence: per CPU cycle, and why that is the honest choice + +The mix is computed **once per CPU cycle** (1.789 MHz NTSC) and handed to `blip`, +which decimates to 44.1 kHz — roughly one output sample per **40.6** CPU cycles. + +Recording at *output* rate would mean choosing which of those ~40 mixes "is" the +sample. Band-limited synthesis makes that choice ill-posed: an output sample is a +weighted sum of transitions across the filter kernel, not a copy of one instant. +A tool that picked one anyway would be answering a question its own signal chain +cannot answer, and would do it confidently. + +So the trace records what was genuinely mixed, at the cadence it was mixed, and +the panel says plainly that one output sample spans ~40.6 of these cycles. This +is the same discipline as the mapper tier gate and the accuracy ledger: state +what is measured, and decline the rest. + +**It is also cheaper than it sounds.** Roughly 29,781 records per NTSC frame +against the pixel store's 61,440 — **0.48x the record count of the video side**. + +| region | CPU cycles/frame | +|---|---| +| NTSC | 29,780 / 29,781 (alternating) | +| PAL | 33,247 | +| **Dendy** | **35,464** | + +The NTSC row is two numbers on purpose. A real NTSC frame is 29,780.5 CPU cycles: +hardware alternates 29,780- and 29,781-cycle frames, because the pre-render +scanline's last dot is skipped on odd frames when rendering is enabled — the same +half-cycle `crates/rustynes-core/src/nes.rs` documents at its frame-duration +constant. So 29,781 is the **upper bound** on a trace's NTSC record count, not a +fixed figure, and a frame that records 29,780 is not short. (The `apu_throughput` +bench drives a fixed 29,780-cycle workload and is a bench, not a frame.) + +`MIX_CAP` is sized from **Dendy**, not NTSC. Sizing it from the number that comes +to mind first would silently truncate the last 16% of every Dendy frame; and when +the cap *is* exceeded the trace reports `truncated()` rather than quietly +returning a short buffer that looks complete. + +## Phase 1 — register attribution + +One slot per address across `$4000-$4017`, each holding `(value, cpu_cycle, pc)`. + +**Last write, not a history.** The question is "what is the register holding, and +who put it there"; a ring would need a retention policy nobody has a principled +value for. The Event Viewer already keeps the per-frame write *sequence* — this +keeps the per-register *cause*, which it does not. + +A `written` flag rather than a sentinel cycle, because **cycle 0 is a legitimate +value**: the reset sequence performs real writes, and a sentinel would misreport +the earliest writes in a run as "never written". + +`$4014` (OAM DMA) and `$4016` (controller strobe) fall inside the range and are +not APU registers. They are tracked anyway and labelled for what they are: the +range is what the bus already classifies as `ApuWrite`, one contiguous index +space costs two slots, and a hole would invite off-by-one arithmetic at every +call site. + +The attribution is **not** cleared per frame — "which instruction last wrote +`$4003`" has an answer that legitimately predates this frame. It is cleared on a +cold boot, where the history it describes genuinely ended, and it starts empty +when you arm it: arming allocates a fresh table, so writes made before Enable was +ticked are not shown. The panel footer says exactly that rather than the +easier-to-write "since the last cold boot", which would be false for anyone who +armed the feature mid-session — which is everyone. + +**Not every write to this range comes from an instruction.** `Apu::reset` +performs an internal `write_register($4015, 0)` modelling the warm-reset +silencing of the channels; it reaches the table through the ordinary CPU path +and would therefore be stamped with whatever PC was last latched. A provenance +tool that answers "who wrote `$4015`?" with a confident, specific, innocent +address is worse than one that declines, so `RegWrite` carries a +`WriteOrigin` — `Instruction` or `Reset` — and the panel prints "APU reset (not +an instruction)" rather than a PC for the latter. The two alternatives were both +worse: suppressing the record entirely would leave the slot advertising the +register's *previous* value after reset genuinely changed it, and a sentinel PC +would be indistinguishable from a real write to address zero. Caught in review of +the PR that introduced the feature, before it shipped. + +## Phase 2 — the mix trace + +Per CPU cycle: the five channel outputs that went into the mix, the expansion +contribution, and the result. The index **is** the cycle offset from +`first_cycle`, so no per-record timestamp is stored. + +Channel values are the raw pre-mix outputs (0-15 for the pulses, triangle and +noise; 0-127 for the DMC) — what the non-linear mixer consumes. They are **not** +scaled by the frontend's mixer gains: those are a presentation control, and +recording post-gain values would make the record describe the user's slider +rather than the chip. + +**The expansion contribution follows the same rule**, and this took a review to +get right. The gated general mix path had a post-gain `ext` in scope and +recorded that, while the default fast path recorded the raw value — so the two +byte-identical paths were recording different things, which is precisely the +divergence this feature's "both paths record" rule exists to prevent. Both now +record the raw value. On a muted expansion channel that means the panel reports +what the cartridge produced rather than zero, exactly as it reports a muted +pulse's output rather than zero. + +`dominant()` compares each channel's share of **its own full scale**, not raw +magnitude, because the raw values are not commensurable — a DMC 127 and a pulse +15 are both "full scale" on different scales. + +## Phase 3 — attribution plumbing + +The split follows the precedent pixel provenance set: the **bus has the PC**, the +**APU has the destination register**, and the PC is pushed down once per +instruction from the existing debug block in `Nes::run_frame`. `rustynes-cpu` is +untouched. + +Both push-down sites are mirrored — `run_frame` and `step_instruction` — so +single-stepping through a `$4003` store in the debugger attributes the write to +the stepped instruction rather than to whatever `run_frame` last left latched. + +Recording happens in `Apu::write_register` **before** the write dispatches, so +the recorded value is what the CPU put on the bus rather than whatever a channel +decided to keep. Both mix paths record: the default-configuration fast +specialization and the gated general path. A record that existed on only one of +two byte-identical paths would be a trap for whoever next changed the other. + +## The trap this feature inherited, and how it was closed up front + +**Pixel provenance shipped non-functional for four releases** — v2.3.2 to v2.3.6 +— because run-ahead's per-frame rollback cleared the store *after* the visible +frame was harvested and *before* the frontend released the emulator lock. The UI +could never observe a populated record. A comment two lines above the clear +asserted the opposite, and that prose is what stopped anyone checking. + +Audio provenance rides the identical rollback. So the carry landed **in the same +change as the feature**, not after a bug report: + +- `Nes::take_audio_provenance` / `put_audio_provenance`, called around + `restore_quiet` in `RunAhead::finish`. +- Save-state loads and netplay rollback still clear, unchanged — those are + genuine timeline changes. Run-ahead's rollback is not; it returns to the + timeline it just left. +- `runahead_preserves_audio_provenance` drives the real produce path at + `run_ahead = 1`, the default, and looks at the first moment the UI could. + **Mutation-checked**: dropping the stash turns it red. +- A control test proves a plain run populates the trace, so a failure of the + run-ahead test cannot be misread as a bad assertion. + +Both assertions are floored at 20,000 records rather than "non-empty", because +the APU's 8-cycle reset sequence alone produces eight records — a non-emptiness +check would pass on a run that emulated nothing at all. + +One further note recorded because it cost time: **a single `run_frame` +immediately after `from_rom` can advance zero cycles**, since the PPU starts at a +frame boundary. The control runs three frames for that reason, exactly as the +pixel-provenance control does. + +## Phase 4 — the panel + +`Tools → Audio → Audio Provenance`, beside Pixel Provenance in intent. + +The panel reads the **core** for the armed state every frame rather than keeping +a mirror. The pixel panel kept one and edge-detected on it, which desynced +permanently the moment a ROM load installed a fresh `Nes` — checkbox ticked, core +unarmed, no way back but unticking and re-ticking. + +It distinguishes three empty states rather than rendering one confident blank +report: *not armed*, *armed but nothing recorded yet*, and *trace truncated*. + +Register rows carry their **side-band effects**, because naming the right +instruction and then describing the wrong effect is its own failure. A write to +`$4003` does not merely set the period — it also loads the length counter, resets +the duty sequencer, and restarts the envelope. Those annotations were confirmed +against this emulator's own implementation (`Pulse::write_timer_hi`, +`Triangle::write_linear`, `Apu::write_status`, and the `$4017` alignment comment +in `Apu::write_register`), not from memory: + +| register | beyond the obvious effect | +|---|---| +| `$4003` / `$4007` | loads length, resets duty sequencer, restarts envelope | +| `$4008` | length-counter halt is **deferred** past the same-cycle half-frame clock | +| `$400B` | loads length, sets the linear-counter reload flag | +| `$400F` | loads length, restarts envelope | +| `$4015` | length enables; the DMC enable is latched and applied with a delay | +| `$4017` | effects land 3 CPU cycles later on an APU clock, 4 otherwise | + +## Determinism and the save state + +Output-only throughout. Nothing recorded is read back into synthesis, and none of +it is serialized. The new `Apu` field is registered in +`snapshot_schema_audit.rs` as output-only with a written reason — the audit +caught it the moment it was added and refused to pass until it was classified. +(It caught **four** fields originally; see "What the bench changed" below.) + +The attribution is deliberately **not** carried in a save state for the same +reason the PPU's `write_attrib` is not: a restored state's registers were not +written by any instruction this session ran, so carrying PCs across a restore +would report a timeline that no longer exists. + +## What the bench changed + +Workstream C is not decoration. The plan required re-running `apu_throughput` +after the plumbing landed, and that re-run reshaped the code **three times**. All +three regressions were invisible in the diff; none would have been found by +reading it. + +The configuration that matters throughout is **feature compiled in, arm off** — +what every user runs, because `crates/rustynes-frontend/Cargo.toml` pulls +`rustynes-core` with `debug-hooks` on unconditionally. "Default-off" here means +the runtime arm, not the code. + +**First:** `record_mix` built the `MixRecord` before testing whether provenance +was armed, so a disarmed build recomputed all five channel outputs every CPU +cycle — and `Pulse::output` is not free, it calls `muted()`, which calls +`sweep_target()`. Measured **+14% to +23%**. The arm check moved to the top. + +**Second:** with the check first, a quiet-host A/B still measured **+9.2% / +−2.0% / +9.7%**. The diagnosis was struct layout — four new inline fields +(`reg_attrib`, `mix_trace`, `attrib_pc`, `attrib_cycle`) sitting among hot +members — and they were consolidated behind a single +`Option>`. + +**That diagnosis was wrong, and the bench said so.** Re-measured after the +consolidation: **+7.98% / +2.88% / +11.03%**, order-bias control +0.11% / +0.76% +/ +0.67%. The consolidation is kept because one pointer is the better shape, but +it is not what fixed anything, and the earlier claim that it would is recorded +here rather than deleted. + +**Third — the actual cause.** The tell was in the numbers all along: the absolute +costs were **+33 µs, +15 µs, +65 µs**, wildly non-uniform. A per-cycle branch +costs a constant number of cycles and cannot produce that shape. `record_mix` was +still being **inlined into `tick_with_external`** — the arm check skipped the +*work*, but the five `output()` calls were still emitted inside the hot function, +inflating it past the point where the mixer and the channel ticks kept their +register allocation and their I-cache line. + +The body is now outlined behind `#[cold] #[inline(never)]`, leaving exactly one +null test on the hot path. Final measurement, disarmed, against a control that +drifted −0.8% to −1.4% over the same interval: + +| workload | outlined vs baseline | order-bias control | net | +|---|---|---|---| +| `apu_tick_silent_frame` | −0.63% | −1.41% | +0.8% — within drift | +| `apu_tick_active_frame` | −5.60% | −0.80% | −4.8% | +| `..._with_external` | +0.00% (p = 0.99) | −0.29% | +0.3% — within drift | + +The disarmed cost is gone. **The −4.8% is NOT claimed as an optimization**: it is +code-layout luck in the favourable direction, of exactly the same kind that +produced the +11% in the unfavourable one, and an unrelated future change will +erase it. Recording it as a win would be adopting noise. + +Three lessons worth carrying: + +- **A default-off feature can charge the default path without executing one line + of its own code.** Twice here, by two different mechanisms. +- **A branch that skips the work does not skip the code.** An early return still + leaves the body inlined in the caller. +- **Non-uniform absolute deltas rule out a per-cycle cost.** That single + observation is what redirected the investigation from layout to inlining, after + the layout fix had already been built and measured. + +## Verification + +- `cargo test -p rustynes-apu --features debug-hooks provenance` — 9 unit tests. +- `cargo test -p rustynes-frontend audio_provenance` — the control and the + run-ahead regression. +- `cargo test -p rustynes-test-harness --test snapshot_schema_audit`. +- `cargo test -p rustynes-apu --no-default-features` and + `cargo clippy -p rustynes-apu --all-targets --no-default-features` — required + because this release adds a feature to a chip crate, and the v2.3.6 VRC7 + defect was a `--no-default-features` build breaking under exactly that change. +- `cargo test -p rustynes-test-harness --features test-roms --test audio_expansion` + — **25 passed** (six expansion-level assertions plus 19 `insta` snapshot + cases, whose snapshots live under `crates/rustynes-test-harness/tests/snapshots`, + not `tests/golden/`). This is the standing APU audio regression gate, and it + belongs in any change that touches the mix path. Added to this list after + review pointed out it was missing. +- AccuracyCoin **141/141** and nestest 0-diff, verified rather than assumed: this + release touches `rustynes-apu`. diff --git a/docs/performance.md b/docs/performance.md index 59f88814..71dfc65b 100644 --- a/docs/performance.md +++ b/docs/performance.md @@ -3797,6 +3797,68 @@ rejected, and D5 declined on inspection; see the §D1 + D6 section above for the numbers and for why a null was the expected result under fat LTO. D2 and D4 remain unmeasured. +### v2.3.7 C2 — the cost a default-OFF feature charged the default path (three findings, all REJECTED-then-fixed) + +Audio provenance (`docs/audio-provenance.md`) is output-only and runtime-default-off. +It still made the shipped APU slower, twice, by two different mechanisms — and the +second diagnosis was wrong before the third one was right. This section records +all three because the sequence is the lesson. + +**The configuration under test throughout is feature-compiled-in, arm-off.** That +is what every user runs: `crates/rustynes-frontend/Cargo.toml` declares +`rustynes-core = { workspace = true, features = ["debug-hooks"] }` with no +condition, so "default-off" describes the runtime arm, not the code. A feature +that is off can only be free if the compiled-in-but-unarmed path is free, and +that is a property to measure, not to assume. + +Method: `apu_throughput` built twice (with and without `debug-hooks`), both +binaries copied aside **before** any measurement so no run is contaminated by its +own compile (the `ab_check.sh` hazard `AGENTS.md` records), then executed on a +host held below 1.00 load, A → B → A, with the trailing A as the order-bias +control. + +| finding | mechanism | measured | disposition | +|---|---|---|---| +| C2a | `MixRecord` built *before* the arm test, so a disarmed build recomputed five channel outputs per CPU cycle | **+14% to +23%** | fixed — arm check hoisted | +| C2b | four new inline `Apu` fields suspected of disturbing hot-member layout | **+9.2% / −2.0% / +9.7%**, then **+7.98% / +2.88% / +11.03%** after consolidating them | **diagnosis REJECTED** — consolidation kept as the better shape, but it fixed nothing | +| C2c | `record_mix` still **inlined** into `tick_with_external`; the branch skipped the work, not the code | **+33 µs / +15 µs / +65 µs** absolute | fixed — outlined behind `#[cold] #[inline(never)]` | + +**What broke C2b open** was the absolute column, not the percentages. +33 µs, ++15 µs and +65 µs on three workloads is not a per-cycle cost: a branch executed +once per CPU cycle costs a constant number of cycles, so it must appear as a +constant number of microseconds, not one that varies four-fold. That single +observation is what redirected the investigation from data layout to code layout +— after the layout fix had already been written, built, and measured. + +Final state, disarmed, against an order-bias control that drifted −0.8% to −1.4% +over the same interval: + +| workload | outlined vs baseline | control | net | +|---|---|---|---| +| `apu_tick_silent_frame` | −0.63% | −1.41% | +0.8% — within drift | +| `apu_tick_active_frame` | −5.60% | −0.80% | −4.8% | +| `apu_tick_active_frame_with_external` | +0.00% (p = 0.99) | −0.29% | +0.3% — within drift | + +**Decision: the disarmed regression is closed; the −4.8% is NOT adopted as a +win.** It is code-layout luck in the favourable direction, the same phenomenon +that produced +11% in the unfavourable one, and it will not survive an unrelated +change to the same function. Claiming it would mean adopting noise, and the +project's own bar — >3% same-runner **and** byte-identical **and** attributable to +the change — is not met by an effect nobody can point at a mechanism for. + +Two rules this adds to the Workstream D findings above: + +- **A branch that skips the work does not skip the code.** An early return leaves + the whole body inlined in the caller, where it costs registers and I-cache even + though it never executes. `#[cold]` + `#[inline(never)]` is how a debug hook + stays free; an early return is not. +- **Non-uniform absolute deltas rule out a per-cycle mechanism.** Read the + microseconds before the percentages when deciding *what kind* of cost you are + looking at. + +The armed path is deliberately pessimized by `#[cold]`. Armed is an interactive +debugging mode; disarmed is every user. + ## Things explicitly *not* in scope for v1.0 - **JIT recompilation** of CPU code. NES games are small enough that interpretation suffices; JIT complicates everything. (Higan/ares don't JIT either.) diff --git a/mkdocs.yml b/mkdocs.yml index d984270e..44217df8 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -134,6 +134,7 @@ nav: - Scripting (Lua): scripting.md - Creator Tools: creator-tools.md - Pixel Provenance: pixel-provenance.md + - Audio Provenance: audio-provenance.md - Latency Oracle: latency-oracle.md - RAM Atlas: ram-atlas.md - CRT / Composite Video: crt-composite.md diff --git a/to-dos/plans/v2.3.7-overtone-plan.md b/to-dos/plans/v2.3.7-overtone-plan.md new file mode 100644 index 00000000..fdd9b89f --- /dev/null +++ b/to-dos/plans/v2.3.7-overtone-plan.md @@ -0,0 +1,321 @@ +# v2.3.7 "Overtone" — Audio Provenance, and the Half Already Written + +**Status:** IN PROGRESS · base `a7407a66` (post-v2.3.6 `main`, green) · v2.3.6 "Sounding" cut 2026-08-18, tagged `3f99a3dd` + +## Goal + +Give audio the causal chain video already has. Point at a moment in the output +waveform and get back **why it sounds like that** — the mixed sample, which +channel dominated it, that channel's live state, the `$4000-$4017` write that set +it, and the CPU instruction and cycle that performed the write. + +Every ingredient but the last one already ships. `audio_scope.rs` plots the +per-channel waveforms, `audio_mixer.rs` exposes per-channel gain, +`Apu::pulse1_out()` and friends expose live channel outputs, and the trace logger +has PC and cycle. **What is missing is the link between a sample and the +instruction that caused it** — precisely the gap the pixel-provenance design +identified for video in v2.3.2, and the reason that feature exists. + +**Two workstreams are already done and in the tree.** This release is partly +written: the VRC7 OPLL save-state defect closed in #398, and six other merged +PRs sit in `[Unreleased]`. They are recorded here as **DONE** so the release +ceremony does not re-derive them from `git log`, and so nobody rebuilds them. + +--- + +## Why this release exists at all + +`docs/accuracy-ledger.md` carried the OPLL row as *"Frontier — documented, not +closed"* from v2.2.3: `Vrc7::save_state` wrote the shadow register bytes and +never the live synthesizer, so after a rewind, netplay rollback, or TAS restore +the FM voice resumed from arbitrary envelope and phase state. Rewind a VRC7 game +and the music came back wrong. That was the most actionable open item in the +ledger, it was audio, and it was a determinism gap in a project whose central +claim is determinism. + +It is now closed — which leaves this release its marquee alone, and a clear +question to answer: **the video side can explain any pixel; audio can explain +nothing.** + +--- + +## Work items + +### A — Audio Provenance (marquee) — **DONE** + +The APU analogue of v2.3.2's Pixel Provenance, built to the same spec shape. +`docs/pixel-provenance.md` (487 lines, phase-structured) is the model, down to +the "what the feature answers" framing. + +#### A0 — READ THIS FIRST: the trap this feature inherits + +**Pixel Provenance shipped non-functional for four releases**, from v2.3.2 until +v2.3.6 fixed it. Run-ahead defaults to 1, and its per-frame rollback cleared both +provenance stores *after* the visible frame was harvested and *before* the UI +could take the lock — so the panel could never observe a populated record. A +comment two lines above the clear asserted the opposite, and that prose is what +stopped anyone checking. + +Audio Provenance rides the same rollback and inherits the same hazard. The fix +already exists and must be extended, not reinvented: + +- `Nes::take_provenance` / `put_provenance` (`crates/rustynes-core/src/nes.rs:915`) +- carried around the restore in `crates/rustynes-frontend/src/runahead.rs:103-107` +- `ProvenanceStash` (`crates/rustynes-ppu/src/provenance.rs:441`) + +**Non-negotiable for this workstream:** + +1. The audio store is carried around run-ahead's rollback, by extending + `ProvenanceStash` or adding its audio equivalent alongside. +2. **Netplay rollback is reasoned about explicitly and written down** — it uses + the same `restore_quiet` path and is *not* the same case. +3. A test drives the real produce path at `run_ahead = 1` and asserts a + populated record survives. That is the test that did not exist for video, and + its absence is the entire reason the defect lived four releases. +4. No comment claims a behaviour the code does not have. If the two disagree, + the code wins and the comment gets corrected *in place, quoting the old + claim*. + +#### A1 — Reuse, do not rebuild + +Exploration confirmed the design is a symmetric mirror of the video side and that +most of the machinery exists. Build nothing that duplicates these: + +| need | reuse | location | +| --- | --- | --- | +| PC + cycle, pushed down once per instruction | `set_attrib_context(pc, cycles)` | `crates/rustynes-core/src/nes.rs:604`, `:674` | +| `$4000-$4017` writes already intercepted and classified | `EventKind::ApuWrite` | `crates/rustynes-core/src/bus.rs:4347` | +| the per-byte attribution shape to copy | `write_attrib: Option>`, `attrib_pc`, `attrib_cycle` | `crates/rustynes-ppu/src/ppu.rs:1096-1125` | +| arm / disarm / accessor API shape | `set_pixel_provenance`, `pixel_provenance`, `clear_pixel_provenance` | `crates/rustynes-core/src/nes.rs:860-899` | +| the register-write entry point | `Apu::write_register` | `crates/rustynes-apu/src/apu.rs:1552` | +| live per-channel outputs | `Apu::pulse1_out` / `pulse2_out` / `triangle_out` / `noise_out` | `crates/rustynes-apu/src/apu.rs:485-500` | + +**One caveat that decides the design.** `EventRec` +(`crates/rustynes-core/src/bus.rs`) carries `kind / scanline / dot / addr / +value` — **no PC, no CPU cycle**, and it is scanline-oriented rather than +sample-oriented. So the event log is the interception *point* worth reusing; it +is not the record. Do not try to make it one. + +#### A2 — Steps + +1. **Add a `debug-hooks` feature to `crates/rustynes-apu/Cargo.toml`.** It + currently declares only `std` — verified, this is real work. Forward it from + `crates/rustynes-core/Cargo.toml:56`, which today reads + `debug-hooks = ["std", "rustynes-ppu/debug-hooks"]` and must gain + `rustynes-apu/debug-hooks`. + + The frontend already pulls the core with `debug-hooks` unconditionally, so — + exactly as with pixel provenance — **the thing that is default-off is the + runtime arm, not the feature**: a lazily-allocated `Option` whose disarmed + cost is one discriminant test per register write. Output-only and + determinism-neutral. + +2. **Per-register write attribution.** 24 entries for `$4000-$4017`, each + carrying `(value, cpu_cycle, pc)`. This is the direct analogue of the PPU's + `write_attrib`, and the attribution split follows the established precedent: + the **bus has the PC**, the **APU has the destination register**, and the PC + is pushed down once per instruction from the existing debug block — so + `rustynes-cpu` is untouched, exactly as it was for video. + +3. **Per-CPU-cycle record** of the channel outputs actually mixed. + + **CORRECTED DURING IMPLEMENTATION.** This step originally said "per-sample" + and sized it at ~734 records/frame (1.2% of the video store). That was wrong, + and the code disproved it: the mix is computed **once per CPU cycle** and + handed to `blip`, which decimates to 44.1 kHz afterwards. Recording at output + rate would mean choosing which of ~40.6 mixes "is" the sample — a choice + band-limited synthesis makes ill-posed, since an output sample is a weighted + sum across the filter kernel rather than a copy of one instant. + + So the trace is per CPU cycle: **~29,781 records/frame NTSC (29,780/29,781 + alternating — see `docs/audio-provenance.md`) against the pixel + store's 61,440 — 0.48x the video record count**, i.e. cheaper than the video + side rather than the 1.2% the estimate claimed. `MIX_CAP` is sized from + **Dendy** (35,464 cycles/frame), not NTSC; sizing from the number that comes + to mind first would silently truncate 16% of every Dendy frame. Over the cap + the trace reports `truncated()` rather than returning a short buffer that + looks complete. + +4. **`Tools → Audio Provenance` panel** + (`crates/rustynes-frontend/src/debugger/audio_provenance_panel.rs`), + cross-linked from `audio_scope.rs` (136 lines) and `audio_mixer.rs` (437 + lines), with "jump to trace" and "break on next write to this register". + + Learn from the video panel's second defect: it shipped with **no click + hit-test at all** while the docs promised "point at any pixel". Whatever + gesture this panel documents, it must implement. + +5. **`docs/audio-provenance.md`**, written in the same change as the code, not + after it. + +#### A3 — Research obligation + +Before wiring the causal chain, confirm against the NESdev APU pages which +register writes have **delayed or side-band effects**, so the chain does not +attribute a change to the wrong write: + +- envelope restart on `$4003` / `$4007` +- length-counter load timing (and the halt/reload-vs-clock ordering v2.1.5 modelled) +- the `$4017` reset delay +- `$4010`-`$4013` DMC interactions + +Record what was checked. A provenance tool that confidently names the wrong +instruction is worse than no tool, on exactly the argument v2.3.6 was built on. + +### B — The VRC7 OPLL save-state defect — **DONE** (#398) + +Closed, not carried. Recorded so it is not re-proposed: + +- `Opll::snapshot` / `Opll::restore` (`OPLL_SNAPSHOT_VERSION` 1, fixed + `OPLL_SNAPSHOT_LEN`) carrying the register shadow, EG/LFO counters, per-channel + patch selection, all 18 operator slots, the user patch pair and the mix. +- VRC7 mapper section **v2**, additive — a v1 blob still loads. A build without + `mapper-audio` writes v1 and validates-then-ignores a v2 tail. +- `load_state` made **atomic**: it parses the tail into a staged value before the + first write, so a rejected load leaves the mapper byte-identical. +- The **parse boundary hardened**. A randomized sweep found four panics reachable + from a hand-edited save state — `patch.tl` and `blk_fnum` indexing the TLL + table, `eg_shift` used as a shift amount, the operator feedback pair summed as + two arbitrary `i32`s, and `eg_rate_l` indexing a 4-entry table. All masked or + clamped at the parse boundary. +- `Opll` registered in `crates/rustynes-test-harness/tests/snapshot_schema_audit.rs`, + which had never been able to see that surface. +- Ledger row now reads *"VRC7 OPLL synthesizer state carried by the mapper save + state (v2.2.3 → **v2.3.7**)"*. + +**The lesson worth carrying into workstream A:** hand-tracing which fields reach +a subscript found one of four panics. A deterministic randomized sweep found the +rest — and the single fixed all-`0xFF` payload *concealed* one, because all-ones +`update_requests` forced a recompute that hid it. If Audio Provenance grows any +parse or restore surface, fuzz it rather than reason about it. + +### C — Carry the APU thread — **DONE, and it earned its place** + +Re-run `apu_throughput` (`crates/rustynes-apu/benches/`) after the `debug-hooks` +plumbing lands, to confirm the **shipped default (hooks off) is unmoved**. The +APU is 18.7% of frame time; a discriminant test per register write should be +invisible, but "should be" is not a measurement. + +**It was not invisible. It was not unmoved. "Should be" was wrong three times.** + +The configuration that matters is feature-compiled-in / arm-off, because +`crates/rustynes-frontend/Cargo.toml` pulls `rustynes-core` with `debug-hooks` +unconditionally — so "default-off" describes the runtime arm, not the code, and +every user compiles this in. + +| # | mechanism | measured | outcome | +|---|---|---|---| +| C2a | `MixRecord` built *before* the arm test — a disarmed build recomputed five channel outputs per CPU cycle | +14% to +23% | fixed: arm check hoisted | +| C2b | suspected `Apu` field-layout disturbance from four new inline fields | +9.2% / −2.0% / +9.7%, then +7.98% / +2.88% / +11.03% after consolidating them behind one `Option>` | **diagnosis REJECTED** — the consolidation is kept as the better shape but fixed nothing | +| C2c | the body was still **inlined** into `tick_with_external`; the branch skipped the work, not the code | +33 µs / +15 µs / +65 µs absolute | fixed: outlined behind `#[cold] #[inline(never)]` | + +What broke C2b open was the absolute column, not the percentages: a branch taken +once per CPU cycle costs a constant number of cycles, so it cannot cost +33 µs on +one workload and +65 µs on another. That observation redirected the investigation +from data layout to code layout — *after* the layout fix had been written, built +and measured. + +Final: disarmed is back to baseline (+0.8% / −4.8% / +0.3% net of an order-bias +control that drifted −0.8% to −1.4%). **The −4.8% is not claimed as a win** — it +is layout luck of the same kind that produced the +11%, and adopting it would be +adopting noise. Method and numbers: `docs/performance.md` §v2.3.7 C2. + +`full_frame` was not run: the two APU regressions were found and closed at the +APU bench, which is the instrument with the resolution to see them, and a +whole-frame bench dilutes an APU effect by roughly 5x. Recorded as a deliberate +omission rather than an oversight. + +**D2 and D4 stay unmeasured on purpose.** Their prior is a null, not an unknown — +see `docs/performance.md`. Do not re-open them without a reason that is not +"they are still on the list". + +### D — Already merged into `[Unreleased]` — record only + +These land in v2.3.7 whichever way the marquee goes. All are on `main` and +already have CHANGELOG entries: + +| PR | | +| --- | --- | +| #396 | **Rad Racer** horizon artifact — `ale_splice` splices from the live `v`, not the ALE-time `address_bus` snapshot | +| #397 | dependency graph refresh; egui/wgpu **held** at 0.35/29 with a `dependabot.yml` `ignore` and the failing wasm error recorded | +| #399 | the **browser** applied no per-game header corrections — third load path to skip them | +| #400 | per-job `timeout-minutes` in `ci.yml`; a hung 4-minute job had silently blocked a release for five hours | +| #401 | `taiki-e/install-action` 2.85.13 → 2.86.1 | +| #402 | `security.yml`'s prebuilt-binary rationale was stale and self-contradictory | +| #403 | the `scanline_frame_180` visual vector #396 moved | + +--- + +## Verification bar + +**Every release, before anything lands** — the standing gate: + +```bash +cargo fmt --all --check +cargo clippy --workspace --all-targets -- -D warnings +cargo clippy -p rustynes-frontend --all-targets --features scripting -- -D warnings +cargo clippy -p rustynes-frontend --all-targets --features scripting,hd-pack -- -D warnings +cargo clippy -p rustynes-frontend --all-targets --features retroachievements -- -D warnings +cargo clippy -p rustynes-frontend --target wasm32-unknown-unknown --lib --bins -- -D warnings +cargo clippy -p rustynes-frontend --target wasm32-unknown-unknown --lib --bins \ + --no-default-features --features wasm-canvas -- -D warnings +RUSTDOCFLAGS="-D warnings" cargo doc --workspace --no-deps +cargo build -p rustynes-core --target thumbv7em-none-eabihf --no-default-features +``` + +Plus, because this release adds a feature to a chip crate: + +```bash +cargo clippy -p rustynes-apu --all-targets --no-default-features -- -D warnings +cargo test -p rustynes-apu --no-default-features +``` + +**The accuracy contract, verified and not asserted** (confirm a non-zero test +count — a filter matching nothing prints `0 passed` and exits 0): + +```bash +cargo test -p rustynes-test-harness --features test-roms --test accuracycoin # 141/141, RAM decoder +cargo test -p rustynes-test-harness --features test-roms --test nestest # 0-diff +cargo test -p rustynes-test-harness --features test-roms --test audio_expansion # 25 passed +``` + +`audio_expansion` was **missing from this list until review caught it** and is +the standing APU audio regression gate: six expansion-level assertions plus 19 +`insta` snapshot cases (snapshots under +`crates/rustynes-test-harness/tests/snapshots`, not `tests/golden/`). Any change +that touches the mix path runs it. + +Audio Provenance is output-only and default-off at the arm, so the shipped +default should be byte-identical **by construction** — verify it anyway. This +release touches `rustynes-apu`, and v2.3.4's lesson is that "by construction" +claims about a crate you edited are the ones that turn out false. + +**Specific to this release:** + +- The `run_ahead = 1` produce-path test (A0.3) must **fail on the unfixed tree + and pass after** — mutation-checked. A test that passes both ways is what + four releases of broken Pixel Provenance looked like. +- Benches before and after the `debug-hooks` plumbing (workstream C). +- `test-roms` is **full-run only** — skipped on feature PRs, run on `main`. Watch + `main` CI to green after merging; #403 is the worked example of what that + catches and a PR cannot. + +--- + +## Carried forward + +- **v2.3.8 "Parallax" — the Divergence Lens.** Two `Nes` instances from one + anchor, advanced in lockstep under differing configuration, first divergence + located by the v2.3.6 probe engine's bisection. Cheap *because* it hands the + diverging pixel to Pixel Provenance and the diverging sample to this release's + Audio Provenance — which is why it comes third. +- **v2.3.9 "Crucible" — testing, performance, correctness, quality.** Its item + A5, *"make `test-roms` reachable at review time"*, has a fresh worked example + in #403 and should be re-read with it in hand. +- **Latency Oracle:** per-game persistence, and the end-to-end millisecond figure + (measured internal lag plus the frontend pipeline cost `perf.rs` tracks). +- **RAM Atlas:** export paths (Watch/Cheat seeding, Lua, RetroAchievements + authoring) and per-game persistence. +- **`libretro/docs#1180`** and the upstream `.info` sync — deferred to **v2.4.0** + by maintainer decision. A **licence change overrides this** and syncs + immediately.