test(cd): DSA/seek trace ring + cd_seek_wedge watchdog signature

libretro.c

@@ -22,6 +22,7 @@ int64_t rfread(void* buffer, size_t elem_size, size_t elem_count, RFILE* stream)
 #include "jagbios.h"
 #include "jaguar.h"
 #include "cdintf.h"
+#include "cdrom.h"
 #include "jagcd_boot.h"
 #include "jagcd_hle.h"
 #include "dac.h"
@@ -341,6 +342,13 @@ static void check_variables(void)
       CrashDetectSetMode(CRASH_DETECT_ON);
    }
 
+   var.key = "virtualjaguar_cd_trace";
+   var.value = NULL;
+   if (environ_cb(RETRO_ENVIRONMENT_GET_VARIABLE, &var) && var.value)
+      CDTraceSetEnabled(strcmp(var.value, "enabled") == 0);
+   else
+      CDTraceSetEnabled(0);
+
    var.key = "virtualjaguar_bios";
    var.value = NULL;
 

libretro_core_options.h

@@ -120,6 +120,20 @@ struct retro_core_option_v2_definition option_defs_us[] = {
       },
       "enabled"
    },
+   {
+      "virtualjaguar_cd_trace",
+      "CD Trace (Diagnostic)",
+      NULL,
+      "Records DSA command/response traffic and seek/FIFO transitions to a bounded ring buffer, dumped to the RetroArch log when the cd_seek_wedge watchdog fires (or on request by test harnesses). Diagnostic only -- intended for troubleshooting Jaguar CD boot/data-transfer bugs, not for normal play. Can also be forced on headlessly via the VJ_CD_TRACE=1 environment variable.",
+      NULL,
+      NULL,
+      {
+         { "disabled", NULL },
+         { "enabled",  NULL },
+         { NULL, NULL },
+      },
+      "disabled"
+   },
    {
       "virtualjaguar_bios",
       "BIOS",

src/cd/cdrom.c

@@ -16,6 +16,7 @@
 #include "cdrom.h"
 
 #include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 #include "cdintf.h"
 #include "jagcd_boot.h"
@@ -302,6 +303,155 @@ static uint16_t DSAQueuePop(void)
 }
 
 
+/* --- CD trace ring: records DSA traffic + seek/FIFO state transitions ---
+ *
+ * Diagnostic-only instrumentation for Task 5's boot-hang triage (see
+ * docs/cd-boot-matrix.md).  Never touches savestates -- all of this is
+ * reset to empty on CDROMReset() the same as the other diag_* counters,
+ * never serialized.
+ *
+ * Toggle: core option `virtualjaguar_cd_trace` (CDTraceSetEnabled(),
+ * called from libretro.c's check_variables()) OR'd with env
+ * VJ_CD_TRACE=1 for headless harness use (CDTraceEnvWantsTrace(), cached
+ * after the first call so getenv() runs at most once per process).
+ *
+ * Zero-cost when off: CDTracePush()'s very first statement is the
+ * `!cdTraceEnabled` branch, so every call site pays exactly one untaken
+ * branch and nothing else -- no extra work, no memory writes.
+ *
+ * Ring size is a power of 2 so the head index wraps with a mask
+ * (`& (CD_TRACE_SIZE - 1)`) instead of modulo -- cheap and, since
+ * cdTraceHead is unsigned, never invokes negative-modulo UB. */
+#define CD_TRACE_SIZE 256
+
+enum
+{
+   CD_TRACE_DSA_TX = 0,     /* DS_DATA write (command sent to drive) */
+   CD_TRACE_DSA_RX,         /* DS_DATA read (response consumed) */
+   CD_TRACE_SEEK_START,     /* $12xx armed a real (non-redundant) seek */
+   CD_TRACE_SEEK_DONE,      /* seekDelay reached 0, $0100 queued */
+   CD_TRACE_FIFO_FILL,      /* fifoDataReady transitioned to true */
+   CD_TRACE_FIFO_DRAIN,     /* FIFO_DRAIN_READS reached, fifoDataReady cleared */
+   CD_TRACE_STOP,           /* $0200 (STOP) command processed */
+   CD_TRACE_HLE_READ        /* HLE CD_read (see jagcd_hle.c) -- carries LBA */
+};
+
+static const char * const cdTraceKindName[] = {
+   "DSA_TX", "DSA_RX", "SEEK_START", "SEEK_DONE",
+   "FIFO_FILL", "FIFO_DRAIN", "STOP", "HLE_READ"
+};
+
+typedef struct
+{
+   uint32_t tick;    /* diag_butchExecCalls at event time -- one tick per
+                         BUTCHExec() invocation, which HalflineCallback()
+                         drives once per halfline (~524 NTSC / ~624 PAL per
+                         frame; see crash_detect.c's halfline comment).
+                         Not itself a frame counter -- cdrom.c has no
+                         direct frame counter in scope -- but monotonic and
+                         fine-grained enough to order events within and
+                         across frames; divide by ~524/2 for a rough NTSC
+                         frame estimate when reading a dump by eye. */
+   uint16_t kind;    /* CD_TRACE_* */
+   uint16_t value;   /* command/response word, or (HLE_READ) low 16 bits
+                         of the requested byte count */
+   uint32_t block;   /* absolute block/LBA at event time */
+} CDTraceEntry;
+
+static CDTraceEntry cdTrace[CD_TRACE_SIZE];
+static uint32_t cdTraceHead = 0;    /* next slot to write (wraps via mask) */
+static uint32_t cdTraceCount = 0;   /* valid entries, saturates at CD_TRACE_SIZE */
+static int cdTraceEnabled = 0;
+static int cdTraceEnvChecked = 0;   /* cache: getenv() runs at most once */
+static int cdTraceEnvWants = 0;
+
+/* Activity counters consumed by crash_detect.c's cd_seek_wedge watchdog
+ * (CDROMDiagGetSeekWedgeState()).  Cheap monotonic uint32 counters -- no
+ * allocation, not part of any savestate. */
+static uint32_t cdSeekStartCount = 0;
+static uint32_t cdSeekDoneCount = 0;
+static uint32_t cdFifoDrainCount = 0;
+
+static int CDTraceEnvWantsTrace(void)
+{
+   const char *e;
+
+   if (cdTraceEnvChecked)
+      return cdTraceEnvWants;
+
+   e = getenv("VJ_CD_TRACE");
+   cdTraceEnvWants = (e != NULL && e[0] == '1') ? 1 : 0;
+   cdTraceEnvChecked = 1;
+   return cdTraceEnvWants;
+}
+
+/* Called from libretro.c's check_variables() with the core option's
+ * enabled/disabled state; always OR'd with the env override so
+ * VJ_CD_TRACE=1 works even for harnesses that never poll core options. */
+void CDTraceSetEnabled(int enabled)
+{
+   cdTraceEnabled = enabled || CDTraceEnvWantsTrace();
+}
+
+static void CDTracePush(uint16_t kind, uint16_t value, uint32_t blk)
+{
+   CDTraceEntry *e;
+
+   if (!cdTraceEnabled)
+      return;
+
+   e = &cdTrace[cdTraceHead & (CD_TRACE_SIZE - 1)];
+   e->tick  = diag_butchExecCalls;
+   e->kind  = kind;
+   e->value = value;
+   e->block = blk;
+   cdTraceHead++;
+   if (cdTraceCount < CD_TRACE_SIZE)
+      cdTraceCount++;
+}
+
+/* Public wrapper for jagcd_hle.c -- the HLE CD_read path performs a
+ * synchronous seek+transfer in one call (no separate seek-delay state
+ * machine like the real-BIOS path), so a single HLE_READ event carrying
+ * the target LBA is the start+done pair for that path. */
+void CDTraceHLERead(uint32_t lba, uint16_t byteCountTrunc)
+{
+   CDTracePush(CD_TRACE_HLE_READ, byteCountTrunc, lba);
+}
+
+void CDTraceDump(void)
+{
+   uint32_t i, n, start;
+   const CDTraceEntry *e;
+
+   if (cdTraceCount == 0)
+   {
+      LOG_INF("[CD-TRACE] ring empty (trace was off, or no events recorded yet)\n");
+      return;
+   }
+
+   n = cdTraceCount;
+   start = (cdTraceHead - n) & (CD_TRACE_SIZE - 1);
+   LOG_INF("[CD-TRACE] dumping %u entries (ring capacity %u)\n", n, (unsigned)CD_TRACE_SIZE);
+   for (i = 0; i < n; i++)
+   {
+      e = &cdTrace[(start + i) & (CD_TRACE_SIZE - 1)];
+      LOG_INF("[CD-TRACE] #%u tick=%u kind=%-10s value=$%04X block=%u\n",
+              i, e->tick, cdTraceKindName[e->kind], e->value, e->block);
+   }
+}
+
+/* Read-only accessor for crash_detect.c's cd_seek_wedge watchdog. Any
+ * pointer may be NULL. */
+void CDROMDiagGetSeekWedgeState(uint32_t *seekStarts, uint32_t *seekDones,
+                                uint32_t *fifoDrains)
+{
+   if (seekStarts) *seekStarts = cdSeekStartCount;
+   if (seekDones)  *seekDones  = cdSeekDoneCount;
+   if (fifoDrains) *fifoDrains = cdFifoDrainCount;
+}
+
+
 void CDROMInit(void)
 {
    haveCDGoodness = CDIntfInit();
@@ -347,6 +497,17 @@ void CDROMReset(void)
    diag_seekCommands = 0;
    diag_butchGlobalDisabled = 0;
 
+   // Trace ring + wedge-watchdog counters are diagnostic state, not part
+   // of the emulated hardware -- reset per game load same as the diag_*
+   // counters above, but cdTraceEnabled itself is a runtime toggle (core
+   // option / env var) and must NOT be reset here or every reset would
+   // silently drop the user's VJ_CD_TRACE=1 / core-option setting.
+   cdTraceHead = 0;
+   cdTraceCount = 0;
+   cdSeekStartCount = 0;
+   cdSeekDoneCount = 0;
+   cdFifoDrainCount = 0;
+
    // Initialize EEPROM to 0xFFFF (blank/erased state), then set
    // factory default values.  The Jaguar CD BIOS reads specific EEPROM
    // addresses during boot and loops if they don't contain expected
@@ -427,6 +588,8 @@ void BUTCHExec(uint32_t cycles)
          // at seek completion — it only becomes available after the GPU ISR
          // processes the DSARX response and re-enables I2CNTRL bit 2.
          DSAQueuePush(0x0100);
+         cdSeekDoneCount++;
+         CDTracePush(CD_TRACE_SEEK_DONE, 0x0100, block);
          cdPlaying = true;
          {
             bool i2sDataEnabled = (cdRam[I2CNTRL + 3] & 0x04) != 0;
@@ -434,6 +597,7 @@ void BUTCHExec(uint32_t cycles)
             {
                fifoDataReady = true;
                fifoReadCount = 0;
+               CDTracePush(CD_TRACE_FIFO_FILL, 0, block);
             }
             else
             {
@@ -461,6 +625,7 @@ void BUTCHExec(uint32_t cycles)
       {
          fifoDataReady = true;
          fifoReadCount = 0;
+         CDTracePush(CD_TRACE_FIFO_FILL, 0, block);
          CD_LOG("BUTCHExec: FIFO half-full — ready for GPU ISR\n");
       }
       else if (fifoFillDelay == 0 && cdPlaying && !i2sDataEnabled)
@@ -801,6 +966,8 @@ TOC: 2 10 00  b 00:00:00 00 54:26:17   <-- Track #11
          dsaResponseReady = false;
          isMultiWordResponse = false;
       }
+
+      CDTracePush(CD_TRACE_DSA_RX, data, block);
    }
    else if (offset == DS_DATA && !haveCDGoodness)
       data = 0x0400;								// No CD interface present, so return error
@@ -835,6 +1002,8 @@ TOC: 2 10 00  b 00:00:00 00 54:26:17   <-- Track #11
          {
             fifoDataReady = false;
             fifoFillDelay = FIFO_REFILL_TICKS;
+            cdFifoDrainCount++;
+            CDTracePush(CD_TRACE_FIFO_DRAIN, (uint16_t)fifoReadCount, block);
          }
       }
    }
@@ -858,6 +1027,8 @@ TOC: 2 10 00  b 00:00:00 00 54:26:17   <-- Track #11
          {
             fifoDataReady = false;
             fifoFillDelay = FIFO_REFILL_TICKS;
+            cdFifoDrainCount++;
+            CDTracePush(CD_TRACE_FIFO_DRAIN, (uint16_t)fifoReadCount, block);
          }
       }
    }
@@ -921,6 +1092,7 @@ void CDROMWriteWord(uint32_t offset, uint16_t data, uint32_t who/*=UNKNOWN*/)
       CD_LOG("DS_DATA write: cmd=0x%04X\n", data);
       cdCmd = data;
       txBufferEmpty = true;  // Per MiSTer: set bit 12 on command write
+      CDTracePush(CD_TRACE_DSA_TX, data, block);
 
       // $10xx/$11xx (Goto Min/Sec): no actual response data, but the BIOS's
       // DSA_tx routine polls BUTCH bit 13 after every command. We must keep
@@ -947,6 +1119,8 @@ void CDROMWriteWord(uint32_t offset, uint16_t data, uint32_t who/*=UNKNOWN*/)
          else
          {
             diag_seekCommands++;
+            cdSeekStartCount++;
+            CDTracePush(CD_TRACE_SEEK_START, data, newBlock);
             dsaResponseReady = false;
             isMultiWordResponse = false;
             seekDelay = SEEK_DELAY_TICKS;
@@ -1013,6 +1187,7 @@ void CDROMWriteWord(uint32_t offset, uint16_t data, uint32_t who/*=UNKNOWN*/)
          }
          // Queue the STOP response in the DSA RX buffer
          DSAQueuePush(0x0200);
+         CDTracePush(CD_TRACE_STOP, 0x0200, block);
       }
       else if ((data & 0xFF00) == 0x0300)			// Read session TOC (5 words)
          cdPtr = 0;

src/cd/cdrom.h

@@ -44,6 +44,32 @@ void CDROMDiagGetCounters(uint32_t *butchExec,
                           uint32_t *globalDisabled,
                           uint32_t *hleBytes);
 
+/* --- CD trace ring (Task 4 instrumentation, see cdrom.c) ---
+ * Diagnostic only; never touches savestates. */
+
+/* Enable/disable the trace ring. Called from libretro.c's check_variables()
+ * with the `virtualjaguar_cd_trace` core option state; internally OR'd
+ * with the VJ_CD_TRACE=1 env override so headless harnesses work even if
+ * they never poll core options. */
+void CDTraceSetEnabled(int enabled);
+
+/* Dump the ring to the RetroArch log (LOG_INF, "[CD-TRACE]" prefix).
+ * Called on-demand (e.g. by crash_detect.c's cd_seek_wedge watchdog) or
+ * by test harnesses that want the DSA conversation leading up to a stall. */
+void CDTraceDump(void);
+
+/* Push a trace event for the HLE CD_read path (src/cd/jagcd_hle.c) -- the
+ * only call site outside cdrom.c, since jagcd_hle.c performs a synchronous
+ * seek+transfer with no separate BUTCH-driven seek/FIFO state machine. */
+void CDTraceHLERead(uint32_t lba, uint16_t byteCountTrunc);
+
+/* Read-only accessor for crash_detect.c's cd_seek_wedge watchdog. Any
+ * pointer may be NULL. seekStarts/seekDones count genuine (non-redundant)
+ * $12xx seeks and their $0100 completions; fifoDrains counts completed
+ * 16-word FIFO drain cycles. */
+void CDROMDiagGetSeekWedgeState(uint32_t *seekStarts, uint32_t *seekDones,
+                                uint32_t *fifoDrains);
+
 #ifdef __cplusplus
 }
 #endif

src/cd/jagcd_hle.c

@@ -17,6 +17,7 @@
 #include "jagcd_hle.h"
 #include "jagcd_boot.h"
 #include "cdintf.h"
+#include "cdrom.h"
 #include "log.h"
 #include "settings.h"
 #include "vjag_memory.h"
@@ -275,6 +276,12 @@ static void HLEHandleCDRead(void)
            (d1 >>  8) & 0x7F,  d1        & 0x7F,
            min, sec, frm, lba, destAddr, a1, byteCount);
 
+   /* HLE_READ trace event: carries the requested LBA (in the `block`
+    * field) so Task 5's wrong-LBA hypothesis can be checked against the
+    * HLE path too, not just the real-BIOS/BUTCHExec path. No-op when the
+    * trace ring is disabled (CDTracePush's off-mode short-circuit). */
+   CDTraceHLERead(lba, (uint16_t)(byteCount > 0xFFFF ? 0xFFFF : byteCount));
+
    if (destAddr == 0 || destAddr >= 0x200000)
    {
       HLE_LOG("CD_read: invalid dest=$%06X — skipping\n", destAddr);

src/core/crash_detect.c

@@ -4,6 +4,8 @@
 #include "log.h"
 #include "../jerry/dsp.h"   /* DSPIsRunning() returns bool -- match the canonical decl */
 #include "../tom/gpu.h"     /* GPUIsRunning() */
+#include "../cd/cdrom.h"    /* CDROMDiagGetSeekWedgeState(), CDTraceDump() */
+#include "settings.h"       /* bootConfig.isCDGame */
 #include <boolean.h>        /* project shim; bool / true / false */
 #include <stdint.h>
 #include <stddef.h>
@@ -41,6 +43,14 @@ extern uint32_t dsp_pc;
 #define WEDGE_FRAMES_DSP   600   /* 10 sec for DSP -- many engines idle on a JR loop */
 #define STALL_FRAMES_FB    300   /* 5 sec of identical framebuffer hash */
 
+/* cd_seek_wedge: a CD seek was issued but the FIFO drain counter (see
+ * CDROMDiagGetSeekWedgeState()) hasn't advanced in this many frames while
+ * a processor is still running. SEEK_DELAY_TICKS in cdrom.c is ~100
+ * halfline ticks (~0.2 frames at NTSC's ~524 halflines/frame) even for a
+ * from-scratch seek, so 300 frames (5 sec) is far beyond any legitimate
+ * seek -- this only fires on a genuine stall. */
+#define WEDGE_FRAMES_CD_SEEK 300
+
 /* Halfline expectation per frame: 524 NTSC, 624 PAL.  Anomaly band is +/- 4. */
 
 /* Verbose-mode heartbeat: dump current state every N frames. */
@@ -64,6 +74,9 @@ static unsigned dsp_same_pc_frames;
 static uint32_t fb_hash_prev;
 static unsigned fb_same_hash_frames;
 
+static uint32_t last_cd_fifo_drains;
+static unsigned cd_seek_wedge_frames;
+
 static unsigned next_heartbeat_frame;
 
 /* Last frame at which each signature fired -- prevents log spam. */
@@ -72,6 +85,7 @@ static unsigned last_log_dsp_escape;
 static unsigned last_log_gpu_wedge;
 static unsigned last_log_dsp_wedge;
 static unsigned last_log_fb_stall;
+static unsigned last_log_cd_seek_wedge;
 
 /* ---------- helpers ---------- */
 
@@ -136,12 +150,15 @@ void CrashDetectReset(void)
    dsp_same_pc_frames = 0;
    fb_hash_prev = 0;
    fb_same_hash_frames = 0;
+   last_cd_fifo_drains = 0;
+   cd_seek_wedge_frames = 0;
    next_heartbeat_frame = HEARTBEAT_FRAMES;
    last_log_gpu_escape = 0;
    last_log_dsp_escape = 0;
    last_log_gpu_wedge = 0;
    last_log_dsp_wedge = 0;
    last_log_fb_stall = 0;
+   last_log_cd_seek_wedge = 0;
 }
 
 void CrashDetectSetMode(int mode)
@@ -157,6 +174,9 @@ void CrashDetectFrameTick(const uint32_t *fb, unsigned w, unsigned h)
    int      gpu_running;
    int      dsp_running;
    uint32_t cur_fb_hash;
+   uint32_t cd_seek_starts;
+   uint32_t cd_seek_dones;
+   uint32_t cd_fifo_drains;
 
    if (!cd_initialized) return;
    if (cd_mode == CRASH_DETECT_OFF) return;
@@ -230,6 +250,47 @@ void CrashDetectFrameTick(const uint32_t *fb, unsigned w, unsigned h)
       fb_same_hash_frames = 0;
    }
 
+   /* ---- CD seek wedge: a seek was issued (real-BIOS/BUTCHExec path) but
+    * the FIFO drain counter has made no progress for WEDGE_FRAMES_CD_SEEK
+    * frames while a processor is still running. Gated on cd_seek_starts
+    * > 0 so non-CD games (and CD games before their first seek) never
+    * evaluate this at all.
+    *
+    * Deliberately broader than "SEEK_START without SEEK_DONE": comparing
+    * fifoDrains instead of seekDones catches both failure shapes Task 5
+    * needs to tell apart -- (a) the seek-completion response never
+    * arrives (seekDones stays behind seekStarts, so fifoDrains obviously
+    * never advances either), and (b) the seek completes fine but the
+    * FIFO continuation dies afterward (seekDones catches up, fifoDrains
+    * still never advances). Either way, the ring dump below shows which
+    * one happened. */
+   if (bootConfig.isCDGame)
+   {
+      CDROMDiagGetSeekWedgeState(&cd_seek_starts, &cd_seek_dones, &cd_fifo_drains);
+
+      if (cd_seek_starts > 0 && cd_fifo_drains == last_cd_fifo_drains
+          && (gpu_running || dsp_running))
+      {
+         cd_seek_wedge_frames++;
+         if (cd_seek_wedge_frames == WEDGE_FRAMES_CD_SEEK
+             && may_log(&last_log_cd_seek_wedge))
+         {
+            LOG_ERR("[CRASH-DETECT] cd_seek_wedge frame=%u seek_starts=%u seek_dones=%u "
+                    "fifo_drains=%u unchanged for %u frames gpu_pc=$%08X gpu_run=%d "
+                    "dsp_pc=$%08X dsp_run=%d\n",
+                    frame_no, cd_seek_starts, cd_seek_dones, cd_fifo_drains,
+                    WEDGE_FRAMES_CD_SEEK, cur_gpu_pc, gpu_running, cur_dsp_pc, dsp_running);
+            CDTraceDump();
+         }
+      }
+      else
+      {
+         cd_seek_wedge_frames = 0;
+      }
+
+      last_cd_fifo_drains = cd_fifo_drains;
+   }
+
    /* ---- Verbose heartbeat ---- */
    if (cd_mode == CRASH_DETECT_VERBOSE && frame_no >= next_heartbeat_frame)
    {