From 93f920be68e54d8e4aaa0795f4c08af07cf5dd44 Mon Sep 17 00:00:00 2001 From: Raphael Amorim Date: Wed, 3 Jun 2026 00:49:30 +0200 Subject: [PATCH] dang man, it took forever. basically forgot to update dicr sub-offset --- cdrom.jam | 22 +++++++++++++++- cpu.jam | 76 ++++++++++++++++++++++++++++++++++++++++++++++++++++++- dma.jam | 47 ++++++++++++++++++++++++---------- main.jam | 75 ++++++++++++++++++++++++++++++++++++++++++++++++++++++ mdec.jam | 20 ++++++++++++++- tests.jam | 3 +++ 6 files changed, 227 insertions(+), 16 deletions(-) diff --git a/cdrom.jam b/cdrom.jam index c1ba324..0dbcd1b 100644 --- a/cdrom.jam +++ b/cdrom.jam @@ -125,6 +125,7 @@ pub const Cdrom = struct { region: u8, // 0=Japan, 1=America, 2=Europe version: u8, // CDR_VERSION_* index readOngoing: u8, // sector pump active + xaPlaying: u8, // XA-ADPCM streaming active (status reg bit2 ADPBUSY) hasDisc: u8, cmdPending: u8, xaFile: u8, // SetFilter file @@ -164,6 +165,7 @@ pub const Cdrom = struct { state: 0, prevState: 0, pendingCmd: 0, dataReq: 0, mode: 0, discType: 0, region: 1, version: 1, readOngoing: 0, + xaPlaying: 0, hasDisc: 0, cmdPending: 0, xaFile: 0, xaChannel: 0, seekPrec: 1, prevSpeed: 0, @@ -262,7 +264,12 @@ pub const Cdrom = struct { // Status register at offset 0 (always, regardless of bank). pub fn readStatus(self: mut Self) u32 { var r: u32 = (self.index as u32) & 0x3; - // bit 2: xa_playing — always 0 (no audio implementation). + // bit 2 (ADPBUSY): XA-ADPCM streaming active — psxe cdrom_read_status + // returns `xa_playing << 2`. Set when a ReadN/ReadS runs in XA mode. + // (Brave Fencer's FMV polls this; jam hardcoding 0 made the game + // branch away from the decode path — the SECOND trace-diff divergence, + // instr ~368.37M.) + if (self.xaPlaying != 0) { r = r | 0x04; } if (self.paramEmpty()) { r = r | 0x08; } if (!self.paramFull()) { r = r | 0x10; } if (!self.respEmpty()) { r = r | 0x20; } @@ -460,6 +467,7 @@ pub const Cdrom = struct { self.state = CD_STATE_IDLE as u8; self.prevState = CD_STATE_IDLE as u8; self.readOngoing = 0; + self.xaPlaying = 0; return; } self.state = self.prevState; @@ -522,6 +530,9 @@ pub const Cdrom = struct { self.state = CD_STATE_READ as u8; self.prevState = CD_STATE_READ as u8; self.readOngoing = 1; + // psxe impl.c:229/683 — a read in XA-ADPCM mode marks the drive + // as XA-streaming (status bit2 ADPBUSY). The game polls this. + if ((self.mode as u32 & MODE_XA_ADPCM) != 0) { self.xaPlaying = 1; } self.delay = self.readDelay(); return; } @@ -758,6 +769,7 @@ pub const Cdrom = struct { self.pendingLba = 150; self.processSetloc(); self.readOngoing = 0; + self.xaPlaying = 0; self.ifr = 2; self.pushResp(self.getStat()); self.state = CD_STATE_IDLE as u8; @@ -779,6 +791,7 @@ pub const Cdrom = struct { self.pendingCmd = 0; self.busy = 0; self.readOngoing = 0; + self.xaPlaying = 0; return; } if (cmd == CDL_GETID) { @@ -1018,6 +1031,13 @@ pub const Cdrom = struct { return discRead(disc, lba, self.dataBuf.asMutPtr()); } + // TEMP FMV PROBE — CD state for the stuck-loop diagnosis (remove after). + pub fn dbgLba(self: mut Self) u32 { return self.lba; } + pub fn dbgState(self: mut Self) u32 { + return (self.state as u32) | ((self.readOngoing as u32) << 8) + | ((self.pendingCmd as u32) << 16); + } + // Read one byte from the data FIFO (the 0x1F801802 register). pub fn readData(self: mut Self) u32 { if (self.dataReq == 0) { return 0; } diff --git a/cpu.jam b/cpu.jam index 0c37188..0cc3d9f 100644 --- a/cpu.jam +++ b/cpu.jam @@ -29,7 +29,6 @@ const { busRead32, busRead16, busRead8, const { Gpu } = import("gpu"); const { dmaAlloc } = import("dma"); const { irqAlloc } = import("irq"); -const { Vec } = import("std/collections"); const { Bus } = import("bus"); const { Timer } = import("timer"); const { gteAlloc, gteDataRead, gteDataWrite, @@ -43,6 +42,18 @@ const { Disc } = import("disc"); const { Vec } = import("std/collections"); const { print } = import("std/fmt"); +// TEMP REG_TRACE: per-instruction trace for the jam<->psxe divergence diff. +// Emits cols 1-37 (cycle pc opcode r0-31 hi lo) matching psxe REG_TRACE_FMT. +pub extern fn getenv(name: *const[] u8) u64; +pub extern fn fopen(path: u64, mode: *const[] u8) u64; +pub extern fn fprintf(stream: u64, fmt: *const[] u8, ...) i32; +// Downsample window: the FMV-critical divergence is just past the 250M point +// where jam==psxe (config-matched). STRIDE=10000 localizes the frame; then +// re-narrow with STRIDE=1 + START=. +const TRACE_START: u64 = 368820000; +const TRACE_STRIDE: u64 = 1; +const TRACE_END: u64 = 368840000; + const Cpu = struct { pc: u32, nextPc: u32, @@ -59,6 +70,9 @@ const Cpu = struct { branchTaken: u8, halted: u8, cycles: u64, + traceFp: u64, // TEMP REG_TRACE + traceInit: u32, + traceN: u64, }; // COP0 register indices. @@ -114,6 +128,7 @@ pub fn freshCpu() Cpu { loadD: 0, loadV: 0, branch: 0, delaySlot: 0, branchTaken: 0, halted: 0, cycles: 0, + traceFp: 0, traceInit: 0, traceN: 0, }; return c; } @@ -497,6 +512,12 @@ pub fn iSh(c: mut Cpu, opc: u32, bus: Bus, regs: *mut[] u32, cop0: *mut[] u32) { raiseException(c, cop0, CAUSE_ADES); return; } + if (addr == 0x1F8010F4 || addr == 0x1F8010F6) { // TEMP FMV WATCHPOINT: DICR + const wpc: u32 = c.savedPc; + const wv: u32 = t & 0xFFFF; + const wcy: u64 = c.cycles; + print("[wp] sh cyc {wcy} pc {wpc} addr {addr} val {wv}\n"); + } busWrite16(bus, cop0, addr, t & 0xFFFF); } @@ -511,6 +532,21 @@ pub fn iSw(c: mut Cpu, opc: u32, bus: Bus, regs: *mut[] u32, cop0: *mut[] u32) { raiseException(c, cop0, CAUSE_ADES); return; } + if (addr == 0x1F8010F4) { // TEMP FMV WATCHPOINT: DICR (32-bit write) + const wpc: u32 = c.savedPc; + const wv: u32 = t; + const wcy: u64 = c.cycles; + print("[wp] sw cyc {wcy} pc {wpc} addr {addr} val {wv}\n"); + } + // TEMP FMV PROBE: catch stores of the four DMA-callback pointers. + // psxe registers ch1=0x800d24d0 (MDEC-out), ch2=0x8005ba90 (GPU), + // ch3=0x800469cc (CD), ch4=0x8003aa18 (SPU). jam has only ch2/ch4. + // Stores of ch2/ch4 reveal the DMA-callback-table address; whether jam + // ever stores ch1/ch3 (and from what PC) shows where it diverges. + if (t == 0x800D24D0 || t == 0x800469CC || t == 0x8005BA90 || t == 0x8003AA18) { + const rpc: u32 = c.savedPc; + print("[REG] sw pc {rpc} addr {addr} val {t}\n"); + } busWrite32(bus, cop0, addr, t); } @@ -1138,6 +1174,17 @@ pub fn cpuIrqPending(cop0: *mut[] u32) bool { // One CPU cycle: latch PC, fetch, advance, dispatch. pub fn step(c: mut Cpu, bus: Bus, regs: *mut[] u32, cop0: *mut[] u32) { c.savedPc = c.pc; + // TEMP FMV PROBE: the STR per-frame clock advancer 0x800d24d0 is never + // run in jam (clock frozen at 0). Catch whether/when it IS reached and + // who calls it (ra), plus the branch 0x800d2550 (a0 = [0x800EC9F0]). + if (c.savedPc == 0x800D24D0) { + const cra: u32 = regs[31]; + print("[CLKFN] entry ra {cra}\n"); + } + if (c.savedPc == 0x800D2550) { + const ba0: u32 = regs[4]; + print("[CLKBR] 0x800d2550 a0 {ba0}\n"); + } c.delaySlot = c.branch; c.branch = 0; c.branchTaken = 0; @@ -1190,6 +1237,33 @@ pub fn step(c: mut Cpu, bus: Bus, regs: *mut[] u32, cop0: *mut[] u32) { var fetchCyc: u64 = 0; if (inBios) { fetchCyc = 18; } + // TEMP REG_TRACE: emit cols 1-37 (cycle pc opcode r0-31 hi lo), matching + // psxe REG_TRACE_FMT's first 37 cols, after fetch-cost + before the IRQ + // check (psxe cpu.c order). Env-gated by PSX_REG_TRACE. + if (c.traceInit == 0) { + c.traceInit = 1; + var evn: []u8 = "PSX_REG_TRACE"; + const ep: u64 = getenv(evn.ptr); + if (ep != 0) { + var wmode: []u8 = "w"; + c.traceFp = fopen(ep, wmode.ptr); + } + } + if (c.traceFp != 0) { + const ic: u64 = c.traceN; + c.traceN = ic + 1; + if (ic >= TRACE_START && ic < TRACE_END && ((ic - TRACE_START) % TRACE_STRIDE) == 0) { + const topc: u32 = busRead32(bus, c.savedPc); + var tfmt: []u8 = "%llu %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x %08x\n"; + fprintf(c.traceFp, tfmt.ptr, c.cycles, c.savedPc, topc, + regs[0], regs[1], regs[2], regs[3], regs[4], regs[5], regs[6], regs[7], + regs[8], regs[9], regs[10], regs[11], regs[12], regs[13], regs[14], regs[15], + regs[16], regs[17], regs[18], regs[19], regs[20], regs[21], regs[22], regs[23], + regs[24], regs[25], regs[26], regs[27], regs[28], regs[29], regs[30], regs[31], + c.hi, c.lo); + } + } + if (cpuIrqPending(cop0)) { // psxe quirk: a COP2 (GTE) math op "wins" over a pending IRQ — // it executes before the interrupt is taken, and because EPC diff --git a/dma.jam b/dma.jam index c4b0a05..7135b9c 100644 --- a/dma.jam +++ b/dma.jam @@ -18,6 +18,7 @@ const { Bus } = import("bus"); const { Cdrom } = import("cdrom"); const { Mdec } = import("mdec"); const { spuWrite16, spuRead16 } = import("spu"); +const { print } = import("std/fmt"); // TEMP FMV: DICR write logging const { Disc } = import("disc"); const SPU_TFIFO_OFF: u32 = 0x1A8; @@ -127,8 +128,23 @@ pub fn dmaRead32(d: *mut[] u32, off: u32) u32 { return 0; } -pub fn dmaRead16(d: *mut[] u32, off: u32) u32 { return dmaRead32(d, off) & 0xFFFF; } -pub fn dmaRead8(d: *mut[] u32, off: u32) u32 { return dmaRead32(d, off) & 0xFF; } +// Sub-offset byte/halfword reads must extract from the aligned 32-bit +// register, mirroring psxe psx_dma_read16/read8 (which special-case 0x75/0x76 +// = DICR bytes). The old `dmaRead32(off) & mask` returned 0 for any offset not +// 0x70/0x74 (dmaRead32's default) — so a `lbu`/`lhu` of the DICR enable bits +// at 0x1F8010F5/F6 read 0, and Brave Fencer's per-frame DICR-enable RMW then +// wrote the per-channel IRQ enables back as 0 → DMA-completion IRQs stopped +// firing → the FMV's STR clock callback never ran → black screen. (3rd +// trace-diff divergence, instr 368,822,179; the write side already handled +// these sub-offsets, only the read side was broken.) +pub fn dmaRead16(d: *mut[] u32, off: u32) u32 { + const shift: u32 = (off & 2) * 8; + return (dmaRead32(d, off & 0xFFFFFFFC) >> shift) & 0xFFFF; +} +pub fn dmaRead8(d: *mut[] u32, off: u32) u32 { + const shift: u32 = (off & 3) * 8; + return (dmaRead32(d, off & 0xFFFFFFFC) >> shift) & 0xFF; +} pub fn dmaWriteDicr(d: *mut[] u32, val: u32) { // Mirror psxe dma_write_dicr (dma.c:108-118) exactly. Preserve only @@ -426,18 +442,23 @@ pub fn dmaDoSpu(d: *mut[] u32, bus: Bus) { } } d[chBase(4) + F_MADR] = addr; - // Keep BUSY=1 (bit 24), clear TRIG (bit 28) — the channel is now in - // flight. Real hardware takes ~16 cycles per word; we account those - // in d[F_SPU_REMAIN] and dmaUpdate clears BUSY + raises IRQ when it - // hits 0. ps1-tests spu/memory-transfer testDMAWriteTiming polls - // CHCR.enabled and asserts loopCount > 0. - d[chBase(4) + F_CHCR] = (d[chBase(4) + F_CHCR] & (~CHCR_TRIG)) | CHCR_BUSY; + // psxe psx_dma_do_spu completes the transfer instantly, FULLY clears CHCR + // (BUSY off), and raises the ch4 completion IRQ on the NEXT psx_dma_update + // (spu_irq_delay is set then immediately zeroed → IC_DMA ~1 instr later). + // The old jam model kept BUSY for `words*8` cycles (d[F_SPU_REMAIN]) and + // only THEN raised the IRQ — an in-flight-DMA nicety for ps1-tests + // (testDMAWriteTiming), but it DEFERRED the completion IC_DMA by the whole + // transfer time. Brave Fencer's FMV kicks an SPU DMA (CHCR @1f8010c8 = + // 0x01000201) then polls I_STAT a few instructions later expecting that + // IC_DMA; the deferral made jam miss the poll, so the game never dispatched + // its DMA-IRQ handler — which is what advances the FMV's STR frame clock + // (0x800d24d0) — and the video stayed black. (Trace-diff vs psxe-strict + // pinned this as the FIRST jam<->psxe divergence, instr 280,834,781.) + // Match psxe: clear CHCR now + raise the ch4 done flag immediately so + // dmaUpdate folds it into DICR.DMA4FL → IC_DMA on the next instruction. + d[chBase(4) + F_CHCR] = 0; d[chBase(4) + F_BCR] = 0; - // Hardware is ~16 cycles/word; our CPU clocks 2 cycles per instruction - // (cpu.jam steps c.cycles += 2), so we use 8 to land inside the - // 16*words*[0.1, 1.1] tolerance window the test expects (ps1-tests - // spu/memory-transfer testDMAWriteTiming / testDMAReadTiming). - d[F_SPU_REMAIN] = words * 8; + d[27] = 1; } pub fn dmaDoOtc(d: *mut[] u32, bus: Bus) { diff --git a/main.jam b/main.jam index 6c9d2b1..6db8c8a 100644 --- a/main.jam +++ b/main.jam @@ -98,6 +98,9 @@ const Cpu = struct { branchTaken: u8, halted: u8, cycles: u64, + traceFp: u64, // TEMP REG_TRACE (mirror cpu.jam) + traceInit: u32, + traceN: u64, }; const Sdl = struct { @@ -678,6 +681,78 @@ fn main() { bus.timer.setDotclock(dm); const is24bpp: bool = (dm & 0x10) != 0; const displayOff: bool = (gpuState[46] & 0x00800000) != 0; + // TEMP FMV PROBE — state disambiguation (stuck vs reaching the FMV). + // Prints poly count + display mode + 24bpp flag every 120 frames; the + // FMV turns 24bpp ON, while the stuck resource-loop freezes the poly + // counter with dm staying 0x27 / is24=0. Remove after the grind. + winStartFrames = winStartFrames + 1; + if (winStartFrames % 120 == 0) { + const pf: u32 = winStartFrames; + const ppoly: u32 = bus.gpu.familyCount(1); + const pdm: u32 = dm; + var p24: u32 = 0; + if (is24bpp) { p24 = 1; } + const plba: u32 = bus.cdrom.dbgLba(); + const pcd: u32 = bus.cdrom.dbgState(); + const pcdState: u32 = pcd & 0xFF; + const pcdRead: u32 = (pcd >> 8) & 0xFF; + const pcdCmd: u32 = (pcd >> 16) & 0xFF; + const pdec: u32 = bus.mdec.dbgDecodeCount(); + const pdcmd: u32 = bus.mdec.dbgDecCmdCount(); + const pallcmd: u32 = bus.mdec.dbgCmdWriteCount(); + const pstr: u32 = bus.mdec.dbgStatusReadCount(); + const ppc: u32 = c.pc; + // The stuck main loop busy-waits for the counter at 0x8006CBB8 to + // reach a target (likely the VBlank-callback frame counter). Watch + // it: if it never advances, the VSync wait never completes. + const vctr: u32 = busRead32(bus, 0x8006CBB8); + // FMV STR scheduler state: frame index [0x800EC9CC] + frame-clock + // counter [0x800EC9D0] (lh). The decode is gated on this clock + // reaching per-frame target times — watch whether it advances. + const sIdx: u32 = busRead32(bus, 0x800EC9CC) & 0xFFFF; + const sClk: u32 = busRead32(bus, 0x800EC9D0) & 0xFFFF; + print("[probe] f {pf} | cd lba {plba} | mdec dec {pdec} | vctr {vctr} | strIdx {sIdx} strClk {sClk}\n"); + // One-shot dump of the CALLER (the per-frame FMV loop) around ra, + // captured mid-streaming. ra points just after the jal to the vsync + // wait, so [ra-0xA0, ra+0x20] covers the calling loop's body. + if (winStartFrames == 1800) { + // Disassembly dump of 0x800d2c88 — the per-frame decode fn the + // scheduler calls; should advance the STR clock + decode but + // doesn't. Its internal gate (likely a hardware-status read) is + // the next layer of the bug. + // DMA-callback dispatcher state: which channel's callback is + // 0x800d24d0 (the FMV clock-inc), and jam's DICR / I_STAT. + const dicrPtr: u32 = busRead32(bus, 0x8006CBC0); + const dicr: u32 = busRead32(bus, 0x1F8010F4); + const istat: u32 = busRead32(bus, 0x1F801070); + const imask: u32 = busRead32(bus, 0x1F801074); + print("[dma] dicrPtr {dicrPtr} dicr {dicr} istat {istat} imask {imask}\n"); + var ci: u32 = 0; + while (ci < 7) { + const cb: u32 = busRead32(bus, 0x8006CBC4 + ci * 4); + print("[dma] cbTable[{ci}] {cb}\n"); + ci = ci + 1; + } + // 0x800d24d0 is installed as a BIOS event handler into the + // EvCB table at physical 0xE2AC / 0xE2C0. Dump that region to + // read each EvCB's class/status/mode/func — the status field + // tells us whether the event is ENABLED (so VBLANK should fire + // it) or DISABLED (an earlier OpenEvent/EnableEvent divergence). + var ea: u32 = 0x8000E260; + while (ea < 0x8000E300) { + const ew: u32 = busRead32(bus, ea); + print("[evcb] {ea} {ew}\n"); + ea = ea + 4; + } + // libcd STR control struct around the callback pointer. + var la: u32 = 0x8006CBB0; + while (la < 0x8006CC00) { + const lw: u32 = busRead32(bus, la); + print("[lib] {la} {lw}\n"); + la = la + 4; + } + } + } if (fullVram) { sdlBlit(sdl, vram, 0, 0, VRAM_WIDTH, VRAM_HEIGHT, false, displayOff); diff --git a/mdec.jam b/mdec.jam index ef77ade..d0415f3 100644 --- a/mdec.jam +++ b/mdec.jam @@ -72,6 +72,11 @@ pub const Mdec = struct { inputSizeB: u32, outputIndex: u32, outputWords: u32, + dbgDecodes: u32, // TEMP FMV PROBE: count of completed DECODE ops + dbgDecCmd: u32, // TEMP FMV PROBE: count of DECODE commands issued + dbgCmdWrites: u32, // TEMP FMV PROBE: total MDEC0 command words + dbgLastOp: u32, // TEMP FMV PROBE: last MDEC op seen (0..3) + dbgStatusReads: u32, // TEMP FMV PROBE: count of status-reg (0x1824) reads yQuant: [64]u8, uvQuant: [64]u8, scale: [64]i16, @@ -88,7 +93,8 @@ pub const Mdec = struct { inputFull: 0, outputEmpty: 0, enableDma0: 0, enableDma1: 0, recvColor: 0, inputIndex: 0, inputSizeB: 0, - outputIndex: 0, outputWords: 0, + outputIndex: 0, outputWords: 0, dbgDecodes: 0, dbgDecCmd: 0, + dbgCmdWrites: 0, dbgLastOp: 0, dbgStatusReads: 0, yQuant: [0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0, 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0, 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0, @@ -349,6 +355,7 @@ pub const Mdec = struct { const op: u32 = (cmd >> 29) & 7; if (op == MDEC_CMD_NOP) { return; } if (op == MDEC_CMD_DECODE) { + self.dbgDecodes = self.dbgDecodes + 1; // TEMP FMV PROBE self.decodeMacroblock(input, output); return; } @@ -362,6 +369,13 @@ pub const Mdec = struct { } } + // TEMP FMV PROBE: counts of completed decodes + issued DECODE commands. + pub fn dbgDecodeCount(self: mut Self) u32 { return self.dbgDecodes; } + pub fn dbgDecCmdCount(self: mut Self) u32 { return self.dbgDecCmd; } + pub fn dbgCmdWriteCount(self: mut Self) u32 { return self.dbgCmdWrites; } + pub fn dbgLastOpSeen(self: mut Self) u32 { return self.dbgLastOp; } + pub fn dbgStatusReadCount(self: mut Self) u32 { return self.dbgStatusReads; } + // ---------- bus dispatch (mdec.c:287/348) ------------------------ pub fn read32(self: mut Self, output: *mut[] u8, off: u32) u32 { if (off == 0) { @@ -380,6 +394,7 @@ pub const Mdec = struct { return 0xAAAAAAAA; } if (off == 4) { + self.dbgStatusReads = self.dbgStatusReads + 1; // TEMP FMV PROBE // Status register — psxe mdec.c:316. // Bits 0-15 = "number of parameter words remaining MINUS 1" // (nocash: FFFFh = none). DuckStation `(remaining/2)-1`, Avocado @@ -448,6 +463,8 @@ pub const Mdec = struct { } // Start a new command. self.cmd = val; + self.dbgCmdWrites = self.dbgCmdWrites + 1; // TEMP FMV PROBE + self.dbgLastOp = (val >> 29) & 7; // TEMP FMV PROBE self.outputReq = 0; self.outputEmpty = 1; // Clear any stale output count from a prior decode so status @@ -467,6 +484,7 @@ pub const Mdec = struct { self.busy = 0; } else if (op == MDEC_CMD_DECODE) { newWords = val & 0xFFFF; + self.dbgDecCmd = self.dbgDecCmd + 1; // TEMP FMV PROBE } else if (op == MDEC_CMD_SET_QT) { self.recvColor = val & 1; if ((val & 1) != 0) { newWords = 32; } else { newWords = 16; } diff --git a/tests.jam b/tests.jam index 67f7071..7c58843 100644 --- a/tests.jam +++ b/tests.jam @@ -62,6 +62,9 @@ const Cpu = struct { branchTaken: u8, halted: u8, cycles: u64, + traceFp: u64, // TEMP REG_TRACE (mirror cpu.jam) + traceInit: u32, + traceN: u64, }; -- 2.51.2