From db4016b685e5f5b293c0014f53d20e42248ac331 Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Sat, 4 Jul 2026 23:45:49 -0700 Subject: [PATCH] cdrom: model read-start latency + far-seek completion delay (MMX5 FMV fix) Give ReadN/ReadS an initial read delay before the steady-state sector cadence, classify SetLoc as near vs far and drive SeekL/SeekP completion timing off it (the far-seek case PCSX calls out for Rockman X5), and fix GetlocP to report the drive sub-Q position during an active read rather than the last data-ready sector. Previously the CD data-ready cadence was too eager, so the MMX5 intro FMV / CD script never accumulated a valid decode window and the movie player bailed with zero decodes. With faithful read/seek latency the intro cutscene now decodes and plays. debug_server: add a cdrom_command_history TCP command exposing the CD command/seq ring (kind, cmd, params, read MSF, pending/queued state, pc) to back this investigation. Co-Authored-By: Claude Opus 4.8 (1M context) --- runtime/src/cdrom.c | 49 +++++++++-- runtime/src/debug_server.c | 174 +++++++++++++++++++++++++++++++++++++ 2 files changed, 216 insertions(+), 7 deletions(-) diff --git a/runtime/src/cdrom.c b/runtime/src/cdrom.c index c2a41c51..3ab86e82 100644 --- a/runtime/src/cdrom.c +++ b/runtime/src/cdrom.c @@ -139,6 +139,7 @@ static uint64_t command_history_seq; /* Seek target */ static uint8_t seek_min, seek_sec, seek_sect; static int s_setloc_lba = -1; /* LBA captured at SetLoc time */ +static int setloc_seek_far; /* Read state */ static int reading; @@ -240,6 +241,7 @@ uint32_t g_cd_overwrite_last_frame = 0; * MAX_PER_FRAME knob. */ #define VBLANK_CYCLES_NTSC 564480 /* 33.8688 MHz / 60 Hz; matches interrupts.c */ #define CDROM_INSTANT_MAX_PER_FRAME_DEFAULT 32 +#define CDROM_SINGLE_SPEED_SECTOR_CYCLES 451584 /* Runtime-tunable 'instant' budget (step 3). One knob drives three writers: * game.toml [runtime] instant_max_per_frame, the cdrom_instant_rate TCP @@ -324,7 +326,27 @@ uint32_t cdrom_get_burst_total(void) { return s_burst_count; } static int sector_delay_cycles(void) { /* PS1 CPU is 33.8688 MHz. CD-ROM sectors arrive at 75 Hz in 1x * mode, or twice that rate when SetMode bit 7 enables double speed. */ - int base = (mode_reg & 0x80) ? 225792 : 451584; + int base = (mode_reg & 0x80) + ? (CDROM_SINGLE_SPEED_SECTOR_CYCLES / 2) + : CDROM_SINGLE_SPEED_SECTOR_CYCLES; + return apply_speed(base); +} + +static int initial_read_delay_cycles(void) { + /* Beetle/PCSX model an additional read-start latency after ReadN/ReadS. + * In double-speed mode the first sector still waits one 1x sector period; + * subsequent sectors use the steady-state 2x cadence above. */ + int base = (mode_reg & 0x80) + ? CDROM_SINGLE_SPEED_SECTOR_CYCLES + : (CDROM_SINGLE_SPEED_SECTOR_CYCLES * 2); + return apply_speed(base); +} + +static int seek_complete_delay_cycles(void) { + /* PCSX carries a far-SetLoc seek state and explicitly calls out Rockman X5: + * far SeekL/SeekP completes after roughly four 1x sector periods, while a + * near/already-settled seek returns quickly. */ + int base = setloc_seek_far ? (CDROM_SINGLE_SPEED_SECTOR_CYCLES * 4) : 0x800; return apply_speed(base); } @@ -871,7 +893,7 @@ static void start_read_stream(uint8_t cmd) { read_sec = seek_sec; read_sect = seek_sect; read_cmd = cmd; - read_delay = sector_delay_cycles(); + read_delay = initial_read_delay_cycles(); reading = 1; stat_reg |= CDSTAT_READ; /* ENQUEUE: sector-read stream scheduled (due in read_delay cycles). A @@ -975,10 +997,14 @@ static void exec_command(uint8_t cmd) { case 0x02: /* SetLoc */ if (param_count >= 3) { + int current_lba = (last_sector_lba >= 0) + ? last_sector_lba + : msf_to_lba(seek_min, seek_sec, seek_sect); seek_min = bcd_to_bin(param_fifo[0]); seek_sec = bcd_to_bin(param_fifo[1]); seek_sect = bcd_to_bin(param_fifo[2]); s_setloc_lba = msf_to_lba(seek_min, seek_sec, seek_sect); + setloc_seek_far = (abs(current_lba - s_setloc_lba) > 16) ? 1 : 0; } response_push(stat_reg); set_irq(CDIRQ_ACK); @@ -1083,9 +1109,16 @@ static void exec_command(uint8_t cmd) { } case 0x11: { /* GetlocP */ - int lba = (last_sector_lba >= 0) - ? last_sector_lba - : msf_to_lba(read_min, read_sec, read_sect); + int lba; + if (reading) { + /* GetlocP reports the drive/sub-Q position. During a read the + * sector stream has already advanced past the data-ready sector. */ + lba = msf_to_lba(read_min, read_sec, read_sect); + } else if (last_sector_lba >= 0) { + lba = last_sector_lba; + } else { + lba = msf_to_lba(seek_min, seek_sec, seek_sect); + } int rm, rs, rf; int am, as, af; lba_to_msf(lba, 0, &rm, &rs, &rf); @@ -1178,7 +1211,7 @@ static void exec_command(uint8_t cmd) { set_irq(CDIRQ_ACK); pending.cmd = cmd; /* 0x15 or 0x16 — completed in process_pending */ pending.pending = 1; - pending.delay = apply_speed(20000); + pending.delay = seek_complete_delay_cycles(); pending.phase = 1; break; @@ -1286,6 +1319,7 @@ static void process_pending(uint32_t cycles) { case 0x15: /* SeekL complete */ case 0x16: /* SeekP complete */ stat_reg &= ~CDSTAT_SEEK; + setloc_seek_far = 0; response_push(stat_reg); set_irq(CDIRQ_COMPLETE); fire_cdrom_irq(); @@ -1411,6 +1445,7 @@ void cdrom_init(const char* cue_path) { pending.pending = 0; memset(&queued_cmd, 0, sizeof(queued_cmd)); seek_min = seek_sec = seek_sect = 0; + setloc_seek_far = 0; cdrom_debug_clear_sector_history(); if (cue_path) { @@ -1751,7 +1786,7 @@ int cdrom_load_in_progress(void) { X(last_sector_raw_mode) X(last_sector_xa_file) X(last_sector_xa_channel) \ X(last_sector_xa_submode) X(last_sector_xa_coding) \ /* seek target */ \ - X(seek_min) X(seek_sec) X(seek_sect) X(s_setloc_lba) \ + X(seek_min) X(seek_sec) X(seek_sect) X(s_setloc_lba) X(setloc_seek_far) \ /* read stream state */ \ X(reading) X(read_min) X(read_sec) X(read_sect) X(mode_reg) \ X(read_cmd) X(read_delay) X(filter_file) X(filter_channel) X(cd_muted) \ diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index 15c4ba39..e5f97424 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -4872,6 +4872,91 @@ static void handle_cdrom_sector_history_clear(int id, const char *json) send_ok(id); } +static const char *cdrom_command_kind_name(uint8_t kind) +{ + switch (kind) { + case 'C': return "exec"; + case 'Q': return "queued"; + default: return "unknown"; + } +} + +static void handle_cdrom_command_history(int id, const char *json) +{ + int count = json_get_int(json, "count", 128); + if (count < 1) count = 1; + if (count > CDROM_COMMAND_HISTORY_CAP) count = CDROM_COMMAND_HISTORY_CAP; + + int frame_lo = json_get_int(json, "frame_lo", -1); + int frame_hi = json_get_int(json, "frame_hi", -1); + + const CDROMCommandHistoryEntry *entries = NULL; + uint64_t total = cdrom_debug_get_command_history(&entries); + uint64_t oldest = (total > CDROM_COMMAND_HISTORY_CAP) + ? total - CDROM_COMMAND_HISTORY_CAP : 0; + + size_t bufsz = 256u + (size_t)count * 640u; + char *buf = (char *)malloc(bufsz); + if (!buf) { send_err(id, "oom"); return; } + + size_t pos = 0; + int emitted = 0; + pos += snprintf(buf + pos, bufsz - pos, + "{\"id\":%d,\"ok\":true,\"total\":%llu," + "\"oldest\":%llu,\"entries\":[", + id, (unsigned long long)total, + (unsigned long long)oldest); + + uint64_t seq = total; + while (seq > oldest && emitted < count && pos < bufsz - 640) { + seq--; + const CDROMCommandHistoryEntry *e = + &entries[seq % CDROM_COMMAND_HISTORY_CAP]; + if (e->seq != seq) continue; + if (frame_lo >= 0 && (int)e->frame < frame_lo) continue; + if (frame_hi >= 0 && (int)e->frame > frame_hi) continue; + + pos += snprintf(buf + pos, bufsz - pos, + "%s{\"seq\":%llu,\"frame\":%u,\"kind\":\"%s\"," + "\"cmd\":\"0x%02X\",\"param_count\":%u,\"params\":[", + emitted ? "," : "", + (unsigned long long)e->seq, e->frame, + cdrom_command_kind_name(e->kind), + e->cmd, e->param_count); + for (uint8_t i = 0; i < e->param_count && i < 16 && pos < bufsz - 96; i++) { + pos += snprintf(buf + pos, bufsz - pos, + "%s\"0x%02X\"", i ? "," : "", e->params[i]); + } + pos += snprintf(buf + pos, bufsz - pos, + "],\"stat\":\"0x%02X\",\"request\":\"0x%02X\"," + "\"irq_enable\":\"0x%02X\",\"irq_flag\":\"0x%02X\"," + "\"mode\":\"0x%02X\",\"seek_msf\":[%u,%u,%u]," + "\"read_msf\":[%u,%u,%u],\"read_cmd\":\"0x%02X\"," + "\"reading\":%u,\"pending_cmd\":\"0x%02X\"," + "\"pending\":%u,\"queued_cmd\":\"0x%02X\"," + "\"queued\":%u,\"func\":\"0x%08X\",\"pc\":\"0x%08X\"," + "\"i_stat\":\"0x%08X\"}", + e->stat, e->request, e->irq_enable, e->irq_flag, + e->mode, e->seek_min, e->seek_sec, e->seek_sect, + e->read_min, e->read_sec, e->read_sect, e->read_cmd, + e->reading, e->pending_cmd, e->pending_pending, + e->queued_cmd, e->queued_pending, e->func, e->pc, + e->i_stat); + emitted++; + } + + pos += snprintf(buf + pos, bufsz - pos, "],\"emitted\":%d}", emitted); + debug_server_send_line(buf); + free(buf); +} + +static void handle_cdrom_command_history_clear(int id, const char *json) +{ + (void)json; + cdrom_debug_clear_command_history(); + send_ok(id); +} + static void handle_cdrom_trace_clear(int id, const char *json) { (void)json; @@ -4885,6 +4970,9 @@ static void handle_cdrom_trace_dump(int id, const char *json) if (count < 1) count = 1; if (count > CDROM_TRACE_CAP) count = CDROM_TRACE_CAP; + int frame_lo = json_get_int(json, "frame_lo", -1); + int frame_hi = json_get_int(json, "frame_hi", -1); + const CDROMTraceEntry *entries = NULL; uint64_t total = cdrom_debug_get_trace(&entries); uint64_t oldest = (total > CDROM_TRACE_CAP) ? total - CDROM_TRACE_CAP : 0; @@ -4903,6 +4991,8 @@ static void handle_cdrom_trace_dump(int id, const char *json) for (uint64_t seq = start; seq < total && pos < bufsz - 400; seq++) { const CDROMTraceEntry *e = &entries[seq % CDROM_TRACE_CAP]; if (e->seq != seq) continue; + if (frame_lo >= 0 && (int)e->frame < frame_lo) continue; + if (frame_hi >= 0 && (int)e->frame > frame_hi) continue; pos += snprintf(buf + pos, bufsz - pos, "%s{\"seq\":%llu,\"kind\":\"%s\",\"addr\":\"0x%08X\"," "\"val\":\"0x%08X\",\"w\":%u,\"func\":\"0x%08X\"," @@ -4939,6 +5029,7 @@ static const char *dma_trace_kind_name(uint32_t kind) switch (kind) { case 'S': return "start"; case 'C': return "complete"; + case 'W': return "write"; default: return "unknown"; } } @@ -5023,6 +5114,86 @@ static void handle_dma_trace_dump(int id, const char *json) free(buf); } +static void append_word_array(char *buf, size_t bufsz, size_t *pos, + const uint32_t *words, int count) +{ + *pos += snprintf(buf + *pos, bufsz - *pos, "["); + for (int i = 0; i < count && *pos < bufsz - 16; i++) { + *pos += snprintf(buf + *pos, bufsz - *pos, + "%s\"0x%08X\"", i ? "," : "", words[i]); + } + *pos += snprintf(buf + *pos, bufsz - *pos, "]"); +} + +static void handle_dma_cdrom_history(int id, const char *json) +{ + int count = json_get_int(json, "count", 256); + if (count < 1) count = 1; + if (count > DMA_CDROM_HISTORY_CAP) count = DMA_CDROM_HISTORY_CAP; + + int frame_lo = json_get_int(json, "frame_lo", -1); + int frame_hi = json_get_int(json, "frame_hi", -1); + int newest = json_get_int(json, "newest", 0) != 0; + + const DMACDROMHistoryEntry *entries = NULL; + uint64_t total = dma_debug_get_cdrom_history(&entries); + uint64_t oldest = (total > DMA_CDROM_HISTORY_CAP) ? total - DMA_CDROM_HISTORY_CAP : 0; + + size_t bufsz = 256u + (size_t)count * 1152u; + char *buf = (char *)malloc(bufsz); + if (!buf) { send_err(id, "oom"); return; } + + size_t pos = 0; + int emitted = 0; + pos += snprintf(buf + pos, bufsz - pos, + "{\"id\":%d,\"ok\":true,\"total\":%llu,\"oldest\":%llu,\"entries\":[", + id, (unsigned long long)total, (unsigned long long)oldest); + + uint64_t start = newest && total > (uint64_t)count ? total - (uint64_t)count : oldest; + if (start < oldest) start = oldest; + for (uint64_t seq = start; seq < total && emitted < count && pos < bufsz - 1152; seq++) { + const DMACDROMHistoryEntry *e = &entries[seq % DMA_CDROM_HISTORY_CAP]; + if (e->seq != seq) continue; + if (frame_lo >= 0 && (int)e->frame_start < frame_lo) continue; + if (frame_hi >= 0 && (int)e->frame_start > frame_hi) continue; + + pos += snprintf(buf + pos, bufsz - pos, + "%s{\"seq\":%llu,\"frame_start\":%u,\"frame_end\":%u," + "\"start_addr\":\"0x%08X\",\"final_addr\":\"0x%08X\"," + "\"requested_words\":%u,\"moved_words\":%u," + "\"bcr\":\"0x%08X\",\"chcr\":\"0x%08X\",\"dpcr\":\"0x%08X\"," + "\"dicr_start\":\"0x%08X\",\"dicr_end\":\"0x%08X\"," + "\"i_stat_start\":\"0x%08X\",\"i_stat_end\":\"0x%08X\"," + "\"func\":\"0x%08X\",\"pc\":\"0x%08X\"," + "\"lba\":%d,\"sector_size\":%d," + "\"sector_read_pos_start\":%d,\"sector_read_pos_end\":%d," + "\"mode\":\"0x%02X\",\"sector_available_start\":%u," + "\"sector_available_end\":%u,\"completed\":%u," + "\"first_words\":", + emitted ? "," : "", + (unsigned long long)e->seq, e->frame_start, e->frame_end, + e->start_addr, e->final_addr, + e->requested_words, e->moved_words, + e->bcr, e->chcr, e->dpcr, + e->dicr_start, e->dicr_end, + e->i_stat_start, e->i_stat_end, + e->func, e->pc, + e->lba, e->sector_size, + e->sector_read_pos_start, e->sector_read_pos_end, + e->mode, e->sector_available_start, + e->sector_available_end, e->completed); + append_word_array(buf, bufsz, &pos, e->first_words, e->first_count); + pos += snprintf(buf + pos, bufsz - pos, ",\"last_words\":"); + append_word_array(buf, bufsz, &pos, e->last_words, e->last_count); + pos += snprintf(buf + pos, bufsz - pos, "}"); + emitted++; + } + + pos += snprintf(buf + pos, bufsz - pos, "],\"emitted\":%d}", emitted); + debug_server_send_line(buf); + free(buf); +} + extern uint32_t gpu_get_opcode_count(uint8_t op); extern int gpu_get_a0_count(void); @@ -10861,11 +11032,14 @@ static const CmdEntry s_commands[] = { { "cdrom_sector_dump", handle_cdrom_sector_dump }, { "cdrom_sector_history", handle_cdrom_sector_history }, { "cdrom_sector_history_clear", handle_cdrom_sector_history_clear }, + { "cdrom_command_history", handle_cdrom_command_history }, + { "cdrom_command_history_clear", handle_cdrom_command_history_clear }, { "cdrom_trace_dump", handle_cdrom_trace_dump }, { "cdrom_trace_clear", handle_cdrom_trace_clear }, { "dma_state", handle_dma_state }, { "dma_trace_dump", handle_dma_trace_dump }, { "dma_trace_clear", handle_dma_trace_clear }, + { "dma_cdrom_history", handle_dma_cdrom_history }, { "sio_state", handle_sio_state }, { "mc_status", handle_mc_status }, { "spu_status", handle_spu_status },