diff --git a/docs/retrospectives/nr-8px.md b/docs/retrospectives/nr-8px.md new file mode 100644 index 000000000..5b6f56cf8 --- /dev/null +++ b/docs/retrospectives/nr-8px.md @@ -0,0 +1,21 @@ +# nr-8px — retrospective + +- **Implementer:** Nightcrawler +- **Date:** 2026-10-04 +- **PR:** #3341 + +## Two read_joy3 tests pinned NESER's own wrong output and hid a bug + +**What happened.** `test_read_joy3_count_errors` and `_fast` expected "CONFLICTS: 0/1000" and "ERRORS: 0/1000". Mesen2 shows 67/1000 and 15/1000 on the same ROMs: a DMC fetch that halts a `$4016` read deletes a bit on hardware (NESdev "DMA", Register conflicts). NESER never deleted one, and the tests had locked that in. The bug turned up only when Ninja Gaiden's DPCM-safe double read took a different branch from Mesen2's in an exec trace. +**Why.** The expected strings were taken from NESER's own screen. These ROMs print a count and have no pass/fail of their own, so any count passed review. +**Cost.** About an hour tracing Ninja Gaiden before the cause was found. +**Prevent by.** A test whose ROM prints a measurement instead of a verdict pins Mesen2's capture of the same frame (0-px diff), named in the test comment, never NESER's own output. The read_joy3 tests now do. Other `setup_rom_console_test!` lines pinning a number are worth checking the same way. +**Seen before.** nr-nuf ("A test pass count tuned to NESER's own output read as a regression against the reference"). + +## The recorded nr-046 NMI difference made checkpoint comparisons look like regressions + +**What happened.** After the DMC fixes, Ninja Gaiden (frame 900) and Joe & Mac (2700) newly differed from Mesen2 at checkpoints, and 8 ROMs from the bead's list still differed. Their NMI clock logs differed from Mesen2's from NMI 7 on, by a few cycles. The cause was the deliberate nr-046 difference: NESER delays an NMI inside a taken branch, Mesen2 does not. With that one line changed in a throwaway build, 20 of 25 ROMs matched at every checkpoint and none was worse than main. +**Why.** Games that wait for NMI in a branch loop drift by a few cycles every frame in spec mode, so any timing change moves their game state somewhere new. +**Cost.** About an hour of spec-mode checkpoint runs that could not tell a real regression from nr-046 noise. +**Prevent by.** scripts/reference_capture/README.md, "Tracing against Mesen2": add that comparisons against Mesen2 are judged with an NMI-the-Mesen2-way build (latch NMI in `after_cpu_cycle` even when `skip_interrupt_latch_this_cycle` is set) before and after the change, and the spec-mode result is reported separately. +**Seen before.** nr-046, nr-3jh. diff --git a/src/nes/apu/dmc.rs b/src/nes/apu/dmc.rs index f463c0e27..82027be13 100644 --- a/src/nes/apu/dmc.rs +++ b/src/nes/apu/dmc.rs @@ -74,7 +74,7 @@ pub struct Dmc { #[cfg(test)] irq_trigger_count: u32, - // Transfer start delay (1-2 cycles after enabling DMC via $4015) + // Transfer start delay (3-4 cycles after enabling DMC via $4015) transfer_start_delay: u8, // Disable delay (2-3 cycles after disabling DMC via $4015) @@ -129,15 +129,17 @@ impl Dmc { *self = Self::with_region(self.region); } - /// Reinitialize the timer counter to the full period value. + /// Set the timer phase the program starts with after the CPU's reset sequence. /// - /// This is called after the CPU reset sequence completes. The CPU reset - /// runs 7 internal cycles that clock the APU, which would decrement the - /// timer away from its initial value. On real hardware (and in catch-up - /// emulators like Mesen), the timer effectively starts counting from the - /// full period when user code begins, so we restore it here. + /// The timer starts at the full period and is clocked through the reset + /// sequence's 8 cycles, as in Mesen2 (the specification leaves the phase open), + /// so the first output clock comes 420 cycles into the program at rate 0. + /// NESER's reset runs 7 cycles and restores the phase here instead. A timer + /// 8 cycles behind Mesen2's moved every DMC fetch, and with it game state, in + /// Snake's Revenge and the Contra demo (nr-xgb, nr-8px). pub fn reinit_timer_after_reset(&mut self) { - self.timer = self.timer_period.saturating_sub(1); + const RESET_SEQUENCE_CYCLES: u16 = 8; + self.timer = self.timer_period.saturating_sub(1 + RESET_SEQUENCE_CYCLES); } /// Returns true if the DMC has a pending DMA request for the next sample byte. @@ -417,8 +419,10 @@ impl Dmc { // If bytes_remaining is 0, restart the sample if self.bytes_remaining == 0 { self.restart_sample(); - // Delay DMA request by 1-2 cycles based on odd/even CPU cycle - self.transfer_start_delay = Self::delay_for_cpu_cycle(cpu_cycle, 1, 2); + // The load DMA halts on the get cycle of the 2nd APU cycle after the + // write (NESdev "DMA"): the CPU sees it 3 cycles after a write on an + // even cycle, 4 after an odd one, as in Mesen2 (nr-8px). + self.transfer_start_delay = Self::delay_for_cpu_cycle(cpu_cycle, 3, 4); trace_apu!(4; "dmc transfer_start_delay {}", self.transfer_start_delay); } } else { @@ -952,6 +956,56 @@ mod sample_tests { assert_eq!(dmc.bytes_remaining, 17); } + /// Runs one CPU cycle of the DMC as the APU does (delays, then the timer) and + /// returns whether the CPU's DMA check in that cycle sees the request. + fn run_dmc_cycle(dmc: &mut Dmc) -> bool { + dmc.process_clock(); + dmc.clock_timer(); + dmc.cpu_dma_pending() + } + + /// The load DMA after a $4015 write halts on the get cycle of the 2nd APU cycle + /// after the write (NESdev "DMA", Summary): the CPU sees the request 3 cycles + /// after a write on an even cycle and 4 after an odd one, as in Mesen2. Seen + /// earlier, the first fetch of Contra's attract-demo drum came 2 cycles early + /// (nr-8px). + #[test] + fn test_load_dma_after_enable_is_seen_by_the_cpu_three_or_four_cycles_later() { + for (write_cycle, cycles_until_seen) in [(0u64, 3), (1, 4)] { + let mut dmc = Dmc::new(); + dmc.write_sample_length(0x01); + dmc.set_enabled(true, write_cycle); + + for cycle in 1..cycles_until_seen { + assert!( + !run_dmc_cycle(&mut dmc), + "write on cycle {write_cycle}: DMA seen {cycle} cycles after it" + ); + } + assert!( + run_dmc_cycle(&mut dmc), + "write on cycle {write_cycle}: DMA not seen {cycles_until_seen} cycles after it" + ); + } + } + + /// Mesen2 clocks the DMC timer through all 8 cycles of the CPU's reset sequence, + /// so its first output clock comes 428 - 8 = 420 cycles into the program (nr-8px). + #[test] + fn test_timer_after_reset_sequence_ticks_420_cycles_into_the_program() { + let mut dmc = Dmc::new(); + dmc.reinit_timer_after_reset(); + dmc.silence_flag = false; + dmc.shift_register = 0xFF; + + for cycle in 1..420 { + dmc.clock_timer(); + assert_eq!(dmc.output_level, 0, "output clocked on cycle {cycle}"); + } + dmc.clock_timer(); + assert_eq!(dmc.output_level, 2, "no output clock on cycle 420"); + } + #[test] fn test_disable_channel_waits_two_cycles_before_clearing_on_even_cpu_cycle() { let mut dmc = Dmc::new(); diff --git a/src/nes/console/nes.rs b/src/nes/console/nes.rs index c00a9e960..c64c3fd06 100644 --- a/src/nes/console/nes.rs +++ b/src/nes/console/nes.rs @@ -442,10 +442,8 @@ impl Nes { self.bus.borrow_mut().reset(soft_reset, ram_init_mode); self.cpu_mut().reset(soft_reset); - // Reinitialize DMC timer phase after CPU reset. The CPU reset runs 7 - // internal cycles that clock the APU (including the DMC timer). On real - // hardware the timer effectively starts from its full period value once - // user code begins executing, so we restore it to the correct phase. + // Set the DMC timer phase the program starts with: Mesen2's, whose reset + // sequence clocks the timer for 8 cycles (see `reinit_timer_after_reset`). self.apu.borrow_mut().dmc_mut().reinit_timer_after_reset(); if !soft_reset { @@ -2366,7 +2364,7 @@ mod tests { #[test] fn test_dmc_dma_stalls_cpu_on_sample_fetch() { // DMC DMA reads should stall the CPU (RDY low) for 1-4 cycles. - // After set_enabled, there is a transfer_start_delay of 2-3 cycles + // After set_enabled, there is a transfer_start_delay of 3-4 cycles // before the DMA request becomes visible. Run enough ticks for the // delay to expire and the stall to occur. let mut nes = Nes::new(crate::platform::app_context::AppContext::new_with_config( diff --git a/src/nes/cpu/cpu/dma.rs b/src/nes/cpu/cpu/dma.rs index dba6d7672..3150da118 100644 --- a/src/nes/cpu/cpu/dma.rs +++ b/src/nes/cpu/cpu/dma.rs @@ -178,13 +178,18 @@ impl Cpu { apu.dmc_mut().dma_address() }; - let is_controller_read = matches!(read_address, 0x4016 | 0x4017); let single_byte_dmc_fetch = self.dmc_pending_single_byte_fetch(); let skip_first_input_clock = dmc_dma_address .map(|address| Self::should_skip_first_input_clock(read_address, address)) .unwrap_or(false); - let use_dummy_halt_read = - is_controller_read && (!single_byte_dmc_fetch || skip_first_input_clock); + // The halted $4016 read and the resumed one are separate contiguous reads, + // so the pad sees one extra clock and the game loses a bit (NESdev "DMA", + // Register conflicts; Mesen2 the same, nr-8px). The $4017 model is unchanged. + let use_dummy_halt_read = match read_address { + 0x4016 => skip_first_input_clock, + 0x4017 => skip_first_input_clock || !single_byte_dmc_fetch, + _ => false, + }; // Halt cycle: complete the CPU cycle started by read() - the read value is discarded let halted_read_value = self diff --git a/src/nes/cpu/cpu/execute.rs b/src/nes/cpu/cpu/execute.rs index 49838bf72..5a3dfa3b6 100644 --- a/src/nes/cpu/cpu/execute.rs +++ b/src/nes/cpu/cpu/execute.rs @@ -289,16 +289,19 @@ impl Cpu { // 5. Push PCL to stack // 6. Fetch high byte of address + // `operand` holds only the low target byte; PC points at the high one, + // the last byte of the JSR, which is the return address pushed. + // The high byte is read after the pushes, so a JSR whose operand sits + // where the return address is pushed jumps to the pushed byte, and a + // DMC DMA can halt the CPU on that final read (nr-8px). + // Dummy read from stack pointer for cycle 3 self.dummy_read(0x0100 | (self.sp as u16)); - // Push return address (PC - 1) to stack - // PC is already pointing to the next instruction, so PC - 1 is the last byte of JSR - let return_addr = self.pc.wrapping_sub(1); - self.push_word(return_addr); + self.push_word(self.pc); - // Set PC to target address - self.pc = operand; + let high = self.read(self.pc); + self.pc = (u16::from(high) << 8) | operand; } Mnemonic::AND => { let value = self.get_operand_value(op, operand); @@ -809,6 +812,10 @@ impl Cpu { base.wrapping_add(self.y) as u16 } + // JSR fetches only the low target byte here: it reads the high byte last, + // after pushing the return address (see `Mnemonic::JSR` in `execute`). + AddrMode::ABS if op.mnemonic == Mnemonic::JSR => self.read_byte_from_pc() as u16, + // Absolute - return 16-bit address AddrMode::ABS => self.read_word_from_pc(), diff --git a/src/nes/cpu/cpu/tests.rs b/src/nes/cpu/cpu/tests.rs index 4ab474402..73ee49328 100644 --- a/src/nes/cpu/cpu/tests.rs +++ b/src/nes/cpu/cpu/tests.rs @@ -575,6 +575,40 @@ fn test_dmc_dma_overlap_4016_exercises_halt_and_dummy_cycles() { ); } +/// A DMC fetch that halts a $4016 read splits it into two contiguous reads, the +/// halted one and the resumed one, so the pad is clocked twice and the CPU gets +/// the second button (NESdev "DMA", Register conflicts; nr-8px). +#[test] +fn test_dmc_dma_halting_4016_read_clocks_the_pad_twice() { + let (ppu, apu, memory) = create_test_memory(); + let mut cpu = Cpu::new( + TimingMode::Ntsc, + Rc::clone(&memory), + Rc::clone(&ppu), + Rc::clone(&apu), + ); + fake_cartridge(&mut cpu, &[0xA5; 17]); + cpu.bus + .borrow_mut() + .set_button(1, crate::nes::input::Button::B, true); + cpu.bus.borrow_mut().write(0x4016, 1, false); + cpu.bus.borrow_mut().write(0x4016, 0, false); + { + let mut apu = apu.borrow_mut(); + apu.dmc_mut().write_sample_address(0x00); + apu.dmc_mut().write_sample_length(0x01); // 17 bytes, not a single-byte sample + apu.write_enable(0b0001_0000); + apu.dmc_mut().debug_set_transfer_start_delay(0); + apu.dmc_mut().debug_set_dma_pending(true); + } + + let first = cpu.read(0x4016) & 1; + let second = cpu.read(0x4016) & 1; + + assert_eq!(first, 1, "the halted read must return B, the A bit deleted"); + assert_eq!(second, 0, "the next read must return Select"); +} + #[test] fn test_dmc_dma_overlap_4017_get_cycle_returns_dmc_sample_value() { let (ppu, apu, memory) = create_test_memory(); @@ -2570,6 +2604,33 @@ fn test_jsr() { assert_eq!(cpu.bus.borrow_mut().read(0x01FE, false), 0x02); // Low byte of return address } +/// JSR reads the high byte of its target last, after pushing the return address +/// (6502 cycle order: opcode, low byte, stack dummy read, push PCH, push PCL, high +/// byte). A JSR whose high operand byte sits where PCH is pushed therefore jumps to +/// the pushed byte, not to the byte the program held (nr-8px). +#[test] +fn test_jsr_reads_high_target_byte_after_pushing_return_address() { + let (ppu, apu, memory) = create_test_memory(); + let mut cpu = Cpu::new(TimingMode::Ntsc, memory, ppu, apu); + fake_cartridge(&mut cpu, &[]); + cpu.reset(true); + // JSR $1234 at $01FD: its high operand byte is at $01FF, where PCH ($01) is pushed. + cpu.bus.borrow_mut().write(0x01FD, JSR, false); + cpu.bus.borrow_mut().write(0x01FE, 0x34, false); + cpu.bus.borrow_mut().write(0x01FF, 0x12, false); + cpu.pc = 0x01FD; + cpu.sp = 0xFF; + + let initial_cycles = cpu.total_cycles; + cpu.execute(); + + assert_eq!( + cpu.pc, 0x0134, + "the high target byte is read after PCH ($01) overwrote it" + ); + assert_eq!(cpu.total_cycles, initial_cycles + 6, "JSR takes 6 cycles"); +} + #[test] fn test_lda_immediate() { let (ppu, apu, memory) = create_test_memory(); diff --git a/src/nes/integration_tests/apu_audio_tests.rs b/src/nes/integration_tests/apu_audio_tests.rs index 02df98314..c60bca7dc 100644 --- a/src/nes/integration_tests/apu_audio_tests.rs +++ b/src/nes/integration_tests/apu_audio_tests.rs @@ -715,12 +715,10 @@ mod tests { /// /// The DMC continues processing buffered bits even after the output is forced to 0x32. /// - /// Expected alternations: 70. With the hardware-accurate DMC timer - /// initialization (timer starts at full period, not zero), the output unit - /// does not fire during the 7 CPU reset cycles. This shifts the output-unit - /// phase relative to the ROM's instruction sequence, resulting in 70 - /// alternations instead of 64 (which was calibrated against the incorrect - /// timer=0 behavior where the output unit fired immediately during reset). + /// Expected alternations: 71. The count is a heuristic over resampled audio and + /// depends on the DMC timer phase relative to the ROM's instructions: it was 64 + /// with the timer at zero after reset, 70 with it at the full period, and is 71 + /// with Mesen2's phase, clocked through the 8 reset cycles (nr-8px). fn check_four_by_two_dmc_bytes_processed(nes: &mut Nes) -> bool { let mut samples = Vec::new(); while nes.sample_ready() { @@ -728,7 +726,7 @@ mod tests { samples.push(sample); } let alternations = max_alternating_small_steps(&samples); - assert_eq!(alternations, 70); + assert_eq!(alternations, 71); true } diff --git a/src/nes/integration_tests/miscellaneous_tests.rs b/src/nes/integration_tests/miscellaneous_tests.rs index c068e9329..1054a9ab6 100644 --- a/src/nes/integration_tests/miscellaneous_tests.rs +++ b/src/nes/integration_tests/miscellaneous_tests.rs @@ -1456,16 +1456,21 @@ mod tests { ); } + // The counts are Mesen2's: its frame 900 of both ROMs matched NESER's at 0 px + // (zero RAM, 2026-10-04, nr-8px). A DMC fetch that halts a $4016 read deletes + // a bit (NESdev "DMA", Register conflicts), so the DMC's timing decides which + // reads conflict. NESER had pinned 0/1000 for both, its own output, while it + // gave the pad no extra clock. setup_rom_console_test!( test_read_joy3_count_errors, "roms/nes/automated_tests/read_joy3/count_errors.nes", - "CONFLICTS: 0/1000-" + "CONFLICTS: 67/1000-" ); setup_rom_console_test!( test_read_joy3_count_errors_fast, "roms/nes/automated_tests/read_joy3/count_errors_fast.nes", - "ERRORS: 0/1000" + "ERRORS: 15/1000" ); setup_rom_console_test!(