diff --git a/runtime/include/dma.h b/runtime/include/dma.h index dccddd3d..ec86f253 100644 --- a/runtime/include/dma.h +++ b/runtime/include/dma.h @@ -113,9 +113,61 @@ typedef struct DMACDROMHistoryEntry { uint32_t last_words[DMA_CDROM_HISTORY_WORDS]; } DMACDROMHistoryEntry; +/* GPU (CH2) linked-list / ordering-table walk observability. + * + * The walk became cycle-paced rather than drained in one go, which means the + * guest can now overwrite an ordering table that DMA has not finished reading. + * These counters make the two failure modes countable instead of visual: + * - starts_dropped: the guest asked for a new OT transfer while the previous + * walk was still running. start_async_gpu_linked_list() returns early in + * that case, so a whole ordering table is never sent to GP0 and nothing + * said so. A non-zero value is a runtime bug, not a game quirk. + * - cycles_last / cycles_max: how long one walk occupies the guest clock. + * Compare against a frame (564480 cycles NTSC): a walk that spans a frame + * is a walk the guest is rebuilding underneath. + */ +/* One aborted walk. For ch2 only ONE call site can cancel — the guest store + * that clears CHCR bit 24 (dma_write_masked) — so `pc` names the guest code + * that abandoned the ordering table. + * + * `polls` is the discriminator between the two possible fixes: it counts the + * guest's own reads of CHCR(2) during THIS walk. If the guest never read the + * busy bit before clearing it, it believed the transfer had already finished, + * and the defect is that the walk is paced too slowly. If it read the bit, saw + * busy, and cleared anyway, the abort itself is what needs to match hardware. */ +typedef struct { + uint32_t pc; /* guest PC of the CHCR store that aborted the walk */ + uint32_t chcr; /* CHCR value after that store */ + uint32_t nodes; /* ordering-table nodes walked before the abort */ + uint32_t words; /* words already handed to GP0 */ + uint32_t cycles; /* guest cycles the walk had been running */ + uint32_t polls; /* guest reads of CHCR(2) during this walk */ +} DMAGpuOtCancel; + +#define DMA_GPU_OT_CANCEL_RING 8 + +typedef struct { + uint64_t starts; + uint64_t starts_dropped; + uint64_t completes; + uint64_t cancels; + uint32_t nodes_last; + uint32_t words_last; + uint64_t cycles_last; + uint64_t cycles_max; + uint8_t active; + uint8_t sync_drain; /* PSX_GPU_LL_SYNC=1 diagnostic A/B lever */ + uint64_t chcr_reads_total; /* guest reads of CHCR(2), lifetime */ + uint64_t chcr_reads_in_walk; /* ... of those, while a walk was active */ + uint32_t initiator_pc; /* guest store PC that kicked the walk */ + uint32_t cancel_ring_count; /* entries written (may exceed the ring) */ + DMAGpuOtCancel cancel_ring[DMA_GPU_OT_CANCEL_RING]; +} DMAGpuOtStats; + uint64_t dma_debug_get_trace(const DMATraceEntry** out_entries); void dma_debug_clear_trace(void); void dma_debug_get_state(DMADebugState* out); +void dma_debug_get_gpu_ot_stats(DMAGpuOtStats* out); uint64_t dma_debug_get_cdrom_history(const DMACDROMHistoryEntry** out_entries); void dma_debug_clear_cdrom_history(void); diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index 0f5fa5d2..becd571e 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -5870,7 +5870,7 @@ static void handle_dma_state(int id, const char *json) DMADebugState s; dma_debug_get_state(&s); - char buf[2048]; + char buf[4096]; size_t pos = 0; pos += snprintf(buf + pos, sizeof(buf) - pos, "{\"id\":%d,\"ok\":true,\"dpcr\":\"0x%08X\"," @@ -5888,7 +5888,49 @@ static void handle_dma_state(int id, const char *json) s.channels[i].remaining_words, s.channels[i].cycles_accum); } - snprintf(buf + pos, sizeof(buf) - pos, "]}"); + pos += snprintf(buf + pos, sizeof(buf) - pos, "]"); + + /* CH2 ordering-table walk: dropped starts are silent geometry loss. */ + { + DMAGpuOtStats ot; + dma_debug_get_gpu_ot_stats(&ot); + pos += snprintf(buf + pos, sizeof(buf) - pos, + ",\"gpu_ot\":{\"starts\":%llu,\"starts_dropped\":%llu," + "\"completes\":%llu,\"cancels\":%llu,\"nodes_last\":%u," + "\"words_last\":%u,\"cycles_last\":%llu," + "\"cycles_max\":%llu,\"active\":%u,\"sync_drain\":%u}", + (unsigned long long)ot.starts, + (unsigned long long)ot.starts_dropped, + (unsigned long long)ot.completes, + (unsigned long long)ot.cancels, + ot.nodes_last, ot.words_last, + (unsigned long long)ot.cycles_last, + (unsigned long long)ot.cycles_max, + ot.active, ot.sync_drain); + pos += snprintf(buf + pos, sizeof(buf) - pos, + ",\"gpu_ot_chcr\":{\"reads_total\":%llu," + "\"reads_in_walk\":%llu,\"cancel_ring_count\":%u," + "\"initiator_pc\":\"0x%08X\"}," + "\"gpu_ot_cancels\":[", + (unsigned long long)ot.chcr_reads_total, + (unsigned long long)ot.chcr_reads_in_walk, + ot.cancel_ring_count, + ot.initiator_pc); + unsigned n = ot.cancel_ring_count < DMA_GPU_OT_CANCEL_RING + ? ot.cancel_ring_count : DMA_GPU_OT_CANCEL_RING; + for (unsigned k = 0; k < n && pos < sizeof(buf) - 160; k++) { + const DMAGpuOtCancel *c = &ot.cancel_ring[k]; + pos += snprintf(buf + pos, sizeof(buf) - pos, + "%s{\"pc\":\"0x%08X\",\"chcr\":\"0x%08X\"," + "\"nodes\":%u,\"words\":%u,\"cycles\":%u," + "\"polls\":%u}", + k ? "," : "", c->pc, c->chcr, + c->nodes, c->words, c->cycles, c->polls); + } + pos += snprintf(buf + pos, sizeof(buf) - pos, "]"); + } + + snprintf(buf + pos, sizeof(buf) - pos, "}"); debug_server_send_line(buf); } diff --git a/runtime/src/dma.c b/runtime/src/dma.c index 7d9ce988..f49362b2 100644 --- a/runtime/src/dma.c +++ b/runtime/src/dma.c @@ -21,6 +21,8 @@ #include "mdec.h" #include "mod_memory.h" #include "overlay_capture.h" +#include "debug_server.h" +#include "psx_cycles.h" #include "spu.h" #include "audio_trace.h" #include "event_ring.h" @@ -63,6 +65,10 @@ typedef struct { static DMAAsyncChannel mdec_async[2]; static DMAAsyncChannel cdrom_async; static DMAGPULinkedList gpu_linked_list; +static DMAGpuOtStats gpu_ot_stats; +static uint64_t gpu_ot_start_cycle; +static uint32_t gpu_ot_polls_this_walk; + /* ---- CD DMA transfer log ---- */ /* Every forward CH3 DMA that lands below 0x1C0000 (game data region) records @@ -392,8 +398,21 @@ static void cancel_async_transfer(int ch) { cdrom_async.cycles_accum = 0; } if (ch == 2 && gpu_linked_list.active) { + /* An OT walk abandoned mid-flight also loses geometry. Only the guest + * CHCR bit-24 clear in dma_write_masked can reach here for ch2, so + * g_debug_last_store_pc names the guest store that did it. */ + DMAGpuOtCancel *c = &gpu_ot_stats.cancel_ring[ + gpu_ot_stats.cancel_ring_count % DMA_GPU_OT_CANCEL_RING]; + c->pc = g_debug_last_store_pc; + c->chcr = channels[2].chcr; + c->nodes = gpu_linked_list.nodes_processed; + c->words = gpu_linked_list.total_words; + c->cycles = (uint32_t)(psx_cycle_count - gpu_ot_start_cycle); + c->polls = gpu_ot_polls_this_walk; + gpu_ot_stats.cancel_ring_count++; + gpu_ot_stats.cancels++; gpu_ws_end_linked_list(); - dma_gpu_ll_cancel(&gpu_linked_list); + dma_gpu_ll_cancel(&gpu_linked_list); } if (ch >= 0 && ch < 7) { delayed_complete[ch].active = 0; @@ -716,6 +735,12 @@ static void gpu_ll_emit_word(void *opaque, uint32_t address, uint32_t word) { static void gpu_ll_complete(void *opaque, int hit_limit) { (void)opaque; + gpu_ot_stats.completes++; + gpu_ot_stats.nodes_last = gpu_linked_list.nodes_processed; + gpu_ot_stats.words_last = gpu_linked_list.total_words; + gpu_ot_stats.cycles_last = psx_cycle_count - gpu_ot_start_cycle; + if (gpu_ot_stats.cycles_last > gpu_ot_stats.cycles_max) + gpu_ot_stats.cycles_max = gpu_ot_stats.cycles_last; channels[2].madr = hit_limit ? gpu_linked_list.current_addr : 0x00FFFFFFu; gpu_ws_end_linked_list(); @@ -730,8 +755,32 @@ static const DMAGPULinkedListOps gpu_ll_ops = { gpu_ll_complete }; +/* PSX_GPU_LL_SYNC=1 drains the ordering-table walk in one go at start, the way + * this channel behaved before it was sliced across guest cycles. Diagnostic + * A/B lever only: completion fires immediately rather than after the transfer's + * word count, so it is not a faithful restoration of the old timing — it exists + * to answer "is spreading this walk over guest time what breaks the geometry?" + */ +static int gpu_ll_sync_drain(void) { + static int enabled = -1; + if (enabled < 0) { + const char *e = getenv("PSX_GPU_LL_SYNC"); + enabled = (e && *e && *e != '0') ? 1 : 0; + if (enabled) + fprintf(stdout, "psxrecomp: PSX_GPU_LL_SYNC enabled " + "(ordering-table DMA drained synchronously)\n"); + } + return enabled; +} + static void start_async_gpu_linked_list(void) { - if (gpu_linked_list.active) return; + if (gpu_linked_list.active) { + /* The guest asked for a new ordering table while the previous walk was + * still running. Dropping it silently costs a whole frame of geometry; + * count it so a miss is a number rather than a screenshot. */ + gpu_ot_stats.starts_dropped++; + return; + } uint32_t start_addr = psx_mod_gpu_dma_resolve_address(channels[2].madr); gpu_ws_begin_linked_list(); /* This scan only prepares optional widescreen grouping. It does not send @@ -740,6 +789,18 @@ static void start_async_gpu_linked_list(void) { gpu_ws_prepass_linked_list(start_addr); dma_gpu_ll_start(&gpu_linked_list, start_addr, 0x40000u); event_ring_record_aux(EV_DMA_SCHED, 2u, channels[2].chcr); + + gpu_ot_stats.starts++; + gpu_ot_start_cycle = psx_cycle_count; + gpu_ot_polls_this_walk = 0; + + if (gpu_ll_sync_drain()) { + while (gpu_linked_list.active) { + dma_gpu_ll_advance(&gpu_linked_list, + dma_gpu_ll_cycles_to_event(&gpu_linked_list), + &gpu_ll_ops, NULL); + } + } } static uint32_t execute_ch2_gpu(void) { @@ -1205,7 +1266,15 @@ uint32_t dma_read(uint32_t addr) { switch (reg) { case 0x00: return channels[ch].madr; case 0x04: return channels[ch].bcr; - case 0x08: return channels[ch].chcr; + case 0x08: + if (ch == 2) { + gpu_ot_stats.chcr_reads_total++; + if (gpu_linked_list.active) { + gpu_ot_stats.chcr_reads_in_walk++; + gpu_ot_polls_this_walk++; + } + } + return channels[ch].chcr; case 0x0C: return 0; default: goto bad; } @@ -1292,6 +1361,14 @@ void dma_write(uint32_t addr, uint32_t val) { dma_write_masked(addr, val, 0xFFFFFFFFu); } +void dma_debug_get_gpu_ot_stats(DMAGpuOtStats* out) { + if (!out) return; + *out = gpu_ot_stats; + out->initiator_pc = s_dma_ch_initiator_pc[2]; + out->active = gpu_linked_list.active; + out->sync_drain = (uint8_t)gpu_ll_sync_drain(); +} + uint64_t dma_debug_get_trace(const DMATraceEntry** out_entries) { if (out_entries) *out_entries = dma_trace; return dma_trace_seq; diff --git a/runtime/src/dma_gpu_ll.c b/runtime/src/dma_gpu_ll.c index 7882b273..86a7f599 100644 --- a/runtime/src/dma_gpu_ll.c +++ b/runtime/src/dma_gpu_ll.c @@ -2,13 +2,29 @@ #include -/* PSX DMA2 linked-list timing used by the clean-room state machine. The header - * read costs eight guest clocks. A non-empty node then has five setup clocks, - * followed by one clock per payload word. Keeping these as separate events is - * important: the guest CPU can change a packet after it starts DMA and before - * DMA reaches that packet. */ -#define DMA_GPU_LL_HEADER_CYCLES 8u -#define DMA_GPU_LL_SETUP_CYCLES 5u +/* PSX DMA2 linked-list timing. One guest clock for the header word, one per + * payload word, and no separate per-node setup charge — so a whole walk costs + * exactly (nodes + words) cycles. Keeping the header and payload as separate + * events is the point of this state machine and is unaffected by the cost: the + * guest CPU can change a packet after it starts DMA and before DMA reaches + * that packet, and the payload is still read at its own boundary. + * + * These were 8 (header) + 5 (setup) per node, which was never gated against a + * measurement. An ordering table is mostly EMPTY nodes — Final Fantasy VII's + * runs to ot_max 4094 — and each empty slot still paid the full header charge, + * making a walk 3.0x more expensive in guest time than the model this runtime + * shipped and was validated against. Measured on FF7 (SCUS-94163): a 4,807-node + * table cost 52,384 cycles against 17,564, and a 44,010-node table cost 499,187 + * against 161,517 — 88% of an NTSC frame's 564,480 cycles. libgpu polls CHCR + * bit 24, finds the channel still busy, and force-clears the start bit + * (0x800484F0 in FF7), abandoning the rest of the frame's geometry mid-walk. + * + * (nodes + words) is not a new assertion: it is the cost the pre-slicing path + * charged via schedule_delayed_complete(2, actual_words, 1). A non-zero + * per-node overhead may well be real on hardware, but it must arrive with a + * measurement behind it, not a substituted constant. */ +#define DMA_GPU_LL_HEADER_CYCLES 1u +#define DMA_GPU_LL_SETUP_CYCLES 0u static uint32_t resolve_address(const DMAGPULinkedListOps *ops, void *opaque, uint32_t address) { @@ -78,20 +94,27 @@ void dma_gpu_ll_advance(DMAGPULinkedList *state, uint32_t cycles, state->emit_node = 1u; state->phase = DMA_GPU_LL_PHASE_PAYLOAD; state->cycles_remaining = DMA_GPU_LL_SETUP_CYCLES; + /* With no setup charge the payload boundary is this same service, + * so fall through to the payload block below rather than returning. + * cycles_to_event() never reports zero, so returning here would + * spend a scheduler cycle per non-empty node that the cost model + * does not account for. The packet is still read at its own + * boundary, below — not at start — which is what lets the guest + * change it after DMA begins. */ + if (state->cycles_remaining) return; + } else { + state->emit_node = ops->begin_node + ? (uint8_t)(ops->begin_node(opaque, state->current_addr, 0u) != 0) + : 1u; + + if (state->next_addr == 0x00FFFFFFu) { + finish(state, ops, opaque); + return; + } + state->current_addr = resolve_address(ops, opaque, state->next_addr); + state->cycles_remaining = DMA_GPU_LL_HEADER_CYCLES; return; } - - state->emit_node = ops->begin_node - ? (uint8_t)(ops->begin_node(opaque, state->current_addr, 0u) != 0) - : 1u; - - if (state->next_addr == 0x00FFFFFFu) { - finish(state, ops, opaque); - return; - } - state->current_addr = resolve_address(ops, opaque, state->next_addr); - state->cycles_remaining = DMA_GPU_LL_HEADER_CYCLES; - return; } if (state->phase == DMA_GPU_LL_PHASE_PAYLOAD) { diff --git a/runtime/tests/test_dma_gpu_linked_list_timing.c b/runtime/tests/test_dma_gpu_linked_list_timing.c index 37961c90..0e418f62 100644 --- a/runtime/tests/test_dma_gpu_linked_list_timing.c +++ b/runtime/tests/test_dma_gpu_linked_list_timing.c @@ -61,35 +61,60 @@ int main(void) { ram[0x24 / 4] = 0x22222222u; dma_gpu_ll_start(&state, 0x00u, 8u); - CHECK(dma_gpu_ll_cycles_to_event(&state) == 8u); - dma_gpu_ll_advance(&state, 7u, &ops, NULL); + /* One clock for the header word, none for setup: a walk costs exactly + * (nodes + words). See the cost-model note in dma_gpu_ll.c — an 8+5 charge + * per node made an ordering table 3x more expensive than the model this + * runtime was validated against, and the guest aborted the transfer. */ + CHECK(dma_gpu_ll_cycles_to_event(&state) == 1u); CHECK(emitted_count == 0u); - /* Header becomes visible at cycle 8; payload waits for setup. */ + /* Header and its payload land on the same service when setup is free. */ dma_gpu_ll_advance(&state, 1u, &ops, NULL); - CHECK(emitted_count == 0u); - CHECK(dma_gpu_ll_cycles_to_event(&state) == 5u); - dma_gpu_ll_advance(&state, 5u, &ops, NULL); CHECK(emitted_count == 1u && emitted[0] == 0x11111111u); - /* This is the regression: the CPU changes the later packet after DMA has - * started. DMA must read the new value when it reaches that packet. */ + /* This is what the sliced walker exists for, and the cost change must not + * weaken it: the CPU changes a later packet after DMA has started, and DMA + * must read the NEW value when it reaches that packet. */ ram[0x24 / 4] = 0xA5A5A5A5u; - CHECK(dma_gpu_ll_cycles_to_event(&state) == 9u); - dma_gpu_ll_advance(&state, 9u, &ops, NULL); - CHECK(emitted_count == 1u); - dma_gpu_ll_advance(&state, 5u, &ops, NULL); + CHECK(dma_gpu_ll_cycles_to_event(&state) == 2u); /* 1 word + 1 header */ + dma_gpu_ll_advance(&state, 2u, &ops, NULL); CHECK(emitted_count == 2u && emitted[1] == 0xA5A5A5A5u); CHECK(completed == 0u); dma_gpu_ll_advance(&state, 1u, &ops, NULL); CHECK(completed == 1u && hit_limit == 0u && !state.active); + /* Assert the bound rather than describing it. Walk a table of empty nodes + * — the shape an ordering table actually has — and require the total cost + * to be exactly (nodes + words). This is the check that would have caught + * the 8+5 regression. */ + { + const uint32_t NODES = 12u; + memset(ram, 0, sizeof(ram)); + for (uint32_t i = 0; i < NODES - 1u; i++) + ram[i] = ((i + 1u) * 4u); /* empty node -> next */ + ram[NODES - 1u] = 0x00FFFFFFu; /* empty terminator */ + + completed = hit_limit = emitted_count = 0u; + dma_gpu_ll_start(&state, 0x00u, 64u); + uint32_t spent = 0u; + while (state.active && spent < 1000u) { + uint32_t d = dma_gpu_ll_cycles_to_event(&state); + dma_gpu_ll_advance(&state, d, &ops, NULL); + spent += d; + } + CHECK(completed == 1u && hit_limit == 0u); + CHECK(state.nodes_processed == NODES); + CHECK(state.total_words == NODES); /* header words only */ + CHECK(spent == NODES); /* nodes + 0 payload words */ + } + /* A malformed cycle is bounded and reports the safety stop. */ + memset(ram, 0, sizeof(ram)); completed = hit_limit = 0u; ram[0x00 / 4] = 0x00000000u; dma_gpu_ll_start(&state, 0x00u, 1u); - dma_gpu_ll_advance(&state, 8u, &ops, NULL); - dma_gpu_ll_advance(&state, 8u, &ops, NULL); + dma_gpu_ll_advance(&state, 1u, &ops, NULL); + dma_gpu_ll_advance(&state, 1u, &ops, NULL); CHECK(completed == 1u && hit_limit == 1u && !state.active); puts("dma_gpu_linked_list_timing_test: PASS");