From 6e2a36c4c8708aaccb560171fd86fdb33356ea0b Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Mon, 20 Jul 2026 00:06:51 -0700 Subject: [PATCH] observability: always-on production rings + halt-and-serve on opted-in listener Landed while root-causing the Tomba 2 warm-cache boot death; each of these was a hole that blocked attribution on the production binary: - psx_fatal_halt: halt-and-serve is now keyed on the TCP listener being live (debug_server_get_status) instead of the build flavor. A production run with PSX_DEBUG_SERVER=1 + PSX_EXIT_HALT=1 now stays inspectable at the fatal instead of exit(1)ing the evidence away. - debug_server_get_status: was declared in debug_server.h but never implemented; implemented (listener state, port, saved socket error). - event_ring: EVENT_RING_ENABLED=1 unconditionally. The ring records edges only; its production disable predated the production listener and contradicted its own ALWAYS-ON design note. - sp_ring (new): stack-domain (64 KB) transition ring at fntrace_record -- one entry per dispatch whose guest SP crossed a domain, i.e. the provenance record for 'who installed this stack pointer'. - disp_ring (new): 128-entry unconditional dispatch tail (target/ra/sp/ cycle) so the final control-flow sequence before a death is always reconstructable post-mortem. - overlay_loader: the native-call ring (overlay_native_ring recent[]) is now recorded in production too -- each entry names the requested PC and the claiming candidate CRC, which is what finally attributed the wrong-variant native run. Co-Authored-By: Claude Fable 5 --- runtime/include/event_ring.h | 15 ++++---- runtime/include/fntrace.h | 34 ++++++++++++++++ runtime/src/crash_trace.c | 40 ++++++++++--------- runtime/src/debug_server.c | 75 ++++++++++++++++++++++++++++++++++++ runtime/src/fntrace.c | 53 +++++++++++++++++++++++++ runtime/src/overlay_loader.c | 13 +++---- 6 files changed, 196 insertions(+), 34 deletions(-) diff --git a/runtime/include/event_ring.h b/runtime/include/event_ring.h index 9c522cd4..1f82f31a 100644 --- a/runtime/include/event_ring.h +++ b/runtime/include/event_ring.h @@ -28,17 +28,16 @@ extern "C" { #endif -/* The event ring is a dev diagnostic: it is only readable over the TCP - * debug server, which production builds strip (PSX_NO_DEBUG_TOOLS). It is - * not part of the freeze dump, so recording in production is pure - * hot-path cost — disable it there. */ +/* ALWAYS-ON in every build, production included. The ring records EDGES + * (IRQ decisions, I_STAT raises, DMA/CD/timer schedule+fire), not per-poll + * samples, so the hot-path cost is a handful of stores per device event. + * The TCP debug server is compiled into every build too (production runs + * opt the listener in via PSX_DEBUG_SERVER=1), so the ring is readable on + * the exact production binary that exhibits a bug — the Tomba 2 lost + * CD-completion race was only attributable because of this. */ #ifndef EVENT_RING_ENABLED -#ifdef PSX_NO_DEBUG_TOOLS -#define EVENT_RING_ENABLED 0 -#else #define EVENT_RING_ENABLED 1 #endif -#endif /* 64K entries * 48 bytes ~= 3 MB. Covers many frames of transition activity. */ #define EVENT_RING_CAP (1u << 16) diff --git a/runtime/include/fntrace.h b/runtime/include/fntrace.h index 0ac49a8e..c2f39b44 100644 --- a/runtime/include/fntrace.h +++ b/runtime/include/fntrace.h @@ -47,6 +47,40 @@ typedef struct { extern FntraceEntry g_fntrace_ring[FNTRACE_RING_CAP]; extern uint64_t g_fntrace_seq; /* monotonic; index into ring = seq % CAP */ +/* ── Stack-domain transition ring (ALWAYS-ON, every build) ────────────────── + * One entry per dispatch whose guest SP crossed a 64 KB domain since the + * previous dispatch. Quiet in normal execution; fires at genuine stack + * switches (green-thread/coroutine restores, longjmp, kernel ChangeThread, + * crt0 stack init) — the provenance record for "who installed this SP". + * Dumped via the `sp_ring` TCP command. */ +#define SPDOM_RING_CAP 512u +typedef struct { + uint64_t seq; + uint64_t cycle; /* guest cycle at the recording dispatch */ + uint32_t prev_sp; /* sp domain execution came FROM */ + uint32_t new_sp; /* sp observed at this dispatch */ + uint32_t target; /* dispatch target (the code running on the new stack) */ + uint32_t ra; /* caller's return PC at the dispatch */ + uint32_t tcb; /* kernel current-TCB (PCB[0]) at the dispatch */ + uint32_t frame; /* s_frame_count */ +} SpDomainEntry; +extern SpDomainEntry g_spdom_ring[SPDOM_RING_CAP]; +extern uint64_t g_spdom_seq; + +/* Always-on dispatch tail ring: last N dispatches (target/ra/sp/cycle), + * recorded unconditionally so the final control-flow sequence before a death + * is always reconstructable. Dumped via `disp_ring`. */ +#define DISP_TAIL_CAP 128u +typedef struct { + uint64_t cycle; + uint32_t target; + uint32_t ra; + uint32_t sp; + uint32_t pad; +} DispTailEntry; +extern DispTailEntry g_disp_tail[DISP_TAIL_CAP]; +extern uint64_t g_disp_tail_seq; + /* Hot path. Called from psx_dispatch on every entry. Inlinable. */ void fntrace_record(CPUState* cpu, uint32_t target); /* Register the game's text range for one-shot game-start detection. diff --git a/runtime/src/crash_trace.c b/runtime/src/crash_trace.c index af96c7da..17539a9b 100644 --- a/runtime/src/crash_trace.c +++ b/runtime/src/crash_trace.c @@ -583,28 +583,32 @@ void psx_fatal_halt(const char *reason) { psx_crash_trace_dump(g_psx_fatal_reason, NULL); freeze_heartbeat_fatal_dump(g_psx_fatal_reason); } -#ifndef PSX_NO_DEBUG_TOOLS - /* Halt-and-serve: emulation is dead but the rings are not. Keep the - * TCP debug server pumping on this (main) thread so a post-mortem - * client can run wtrace_dump / read_ram / screenshot / etc. against - * the exact crash state. */ - extern void debug_server_poll(void); - fprintf(stderr, - "FATAL: %s — emulation halted; TCP debug server stays live " - "for post-mortem ring queries.\n", g_psx_fatal_reason); - fflush(stderr); - for (;;) { - debug_server_poll(); + /* Halt-and-serve: emulation is dead but the rings are not. Keyed to the + * LISTENER being live, not the build flavor — the server is compiled into + * every build and production runs opt it in via PSX_DEBUG_SERVER=1, so a + * fatal on such a run must stay inspectable instead of exit(1)ing the + * evidence away. Without a listener (a player's release run) there is + * nobody to serve; exit so the process doesn't hang invisibly. */ + { int listening = 0, port = 0, err = 0; + extern void debug_server_get_status(int *listening, int *port, int *error); + debug_server_get_status(&listening, &port, &err); + if (!listening) exit(1); + extern void debug_server_poll(void); + fprintf(stderr, + "FATAL: %s — emulation halted; TCP debug server stays live " + "on port %d for post-mortem ring queries.\n", + g_psx_fatal_reason, port); + fflush(stderr); + for (;;) { + debug_server_poll(); #ifdef _WIN32 - Sleep(1); + Sleep(1); #else - struct timespec req = {0, 1000000}; - nanosleep(&req, NULL); + struct timespec req = {0, 1000000}; + nanosleep(&req, NULL); #endif + } } -#else - exit(1); -#endif } /* ── Crash handlers ──────────────────────────────────────────────────── */ diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index ba272d25..706485b4 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -95,6 +95,7 @@ extern void psx_write_byte(uint32_t addr, uint8_t val); static sock_t s_listen = SOCK_INVALID; static sock_t s_client = SOCK_INVALID; static int s_port = DEFAULT_DEBUG_PORT; +static int s_listen_err = 0; /* platform socket error captured by init */ #define RECV_BUF_SIZE 8192 static char s_recv_buf[RECV_BUF_SIZE]; @@ -8767,6 +8768,69 @@ static void handle_irqctx_ring(int id, const char *json) free(buf); } +/* sp_ring — dump the always-on stack-domain transition ring (fntrace.c). + * One entry per dispatch whose guest SP crossed a 64 KB domain: the + * provenance record for "who installed this stack pointer". */ +static void handle_sp_ring(int id, const char *json) +{ + extern SpDomainEntry g_spdom_ring[]; extern uint64_t g_spdom_seq; + int count = json_get_int(json, "count", 64); + if (count < 1) count = 1; + if (count > (int)SPDOM_RING_CAP) count = (int)SPDOM_RING_CAP; + uint64_t total = g_spdom_seq; + uint32_t avail = total < SPDOM_RING_CAP ? (uint32_t)total : SPDOM_RING_CAP; + uint32_t n = (uint32_t)count < avail ? (uint32_t)count : avail; + size_t BUF_SZ = 256u + (size_t)n * 200u; + char *buf = (char *)malloc(BUF_SZ); if (!buf) { send_err(id, "oom"); return; } + size_t pos = 0; + pos += snprintf(buf + pos, BUF_SZ - pos, + "{\"id\":%d,\"ok\":true,\"total\":%llu,\"entries\":[", + id, (unsigned long long)total); + for (uint32_t i = 0; i < n && pos < BUF_SZ - 256; i++) { + uint64_t idx = total - n + i; + SpDomainEntry *e = &g_spdom_ring[idx % SPDOM_RING_CAP]; + pos += snprintf(buf + pos, BUF_SZ - pos, + "%s{\"seq\":%llu,\"cycle\":%llu,\"frame\":%u," + "\"prev_sp\":\"0x%08X\",\"new_sp\":\"0x%08X\"," + "\"target\":\"0x%08X\",\"ra\":\"0x%08X\",\"tcb\":\"0x%08X\"}", + i ? "," : "", (unsigned long long)e->seq, (unsigned long long)e->cycle, + e->frame, e->prev_sp, e->new_sp, e->target, e->ra, e->tcb); + } + pos += snprintf(buf + pos, BUF_SZ - pos, "]}"); + debug_server_send_line(buf); + free(buf); +} + +/* disp_ring — dump the always-on dispatch tail ring (fntrace.c). */ +static void handle_disp_ring(int id, const char *json) +{ + extern DispTailEntry g_disp_tail[]; extern uint64_t g_disp_tail_seq; + int count = json_get_int(json, "count", 64); + if (count < 1) count = 1; + if (count > (int)DISP_TAIL_CAP) count = (int)DISP_TAIL_CAP; + uint64_t total = g_disp_tail_seq; + uint32_t avail = total < DISP_TAIL_CAP ? (uint32_t)total : DISP_TAIL_CAP; + uint32_t n = (uint32_t)count < avail ? (uint32_t)count : avail; + size_t BUF_SZ = 256u + (size_t)n * 130u; + char *buf = (char *)malloc(BUF_SZ); if (!buf) { send_err(id, "oom"); return; } + size_t pos = 0; + pos += snprintf(buf + pos, BUF_SZ - pos, + "{\"id\":%d,\"ok\":true,\"total\":%llu,\"entries\":[", + id, (unsigned long long)total); + for (uint32_t i = 0; i < n && pos < BUF_SZ - 200; i++) { + uint64_t idx = total - n + i; + DispTailEntry *e = &g_disp_tail[idx % DISP_TAIL_CAP]; + pos += snprintf(buf + pos, BUF_SZ - pos, + "%s{\"seq\":%llu,\"cycle\":%llu,\"target\":\"0x%08X\"," + "\"ra\":\"0x%08X\",\"sp\":\"0x%08X\"}", + i ? "," : "", (unsigned long long)idx, (unsigned long long)e->cycle, + e->target, e->ra, e->sp); + } + pos += snprintf(buf + pos, BUF_SZ - pos, "]}"); + debug_server_send_line(buf); + free(buf); +} + static void handle_freeze_check(int id, const char *json) { int window = json_get_int(json, "window", 256); @@ -12191,6 +12255,8 @@ static const CmdEntry s_commands[] = { { "freeze_check", handle_freeze_check }, { "d44_ring", handle_d44_ring }, { "irqctx_ring", handle_irqctx_ring }, + { "sp_ring", handle_sp_ring }, + { "disp_ring", handle_disp_ring }, { "cyc_watch", handle_cyc_watch }, { "cyc_watch_dump", handle_cyc_watch_dump }, { "cyc_watch_clear", handle_cyc_watch_clear }, @@ -12394,6 +12460,7 @@ void debug_server_init(int port) s_listen = socket(AF_INET, SOCK_STREAM, 0); if (s_listen == SOCK_INVALID) { + s_listen_err = sock_error(); fprintf(stdout, "psxrecomp: debug server socket() FAILED\n"); return; } @@ -12408,6 +12475,7 @@ void debug_server_init(int port) addr.sin_port = htons((uint16_t)s_port); if (bind(s_listen, (struct sockaddr *)&addr, sizeof(addr)) != 0) { + s_listen_err = sock_error(); fprintf(stdout, "psxrecomp: debug server bind(%d) FAILED\n", s_port); sock_close(s_listen); s_listen = SOCK_INVALID; @@ -12831,6 +12899,13 @@ static int io_thread_main(void *arg) return 0; } +void debug_server_get_status(int *listening, int *port, int *error) +{ + if (listening) *listening = (s_listen != SOCK_INVALID); + if (port) *port = s_port; + if (error) *error = s_listen_err; +} + void debug_server_poll(void) { /* Phase 1.0e-e2 starvation watchdog heartbeat. Refreshes the diff --git a/runtime/src/fntrace.c b/runtime/src/fntrace.c index ece9cc68..bb0f5e06 100644 --- a/runtime/src/fntrace.c +++ b/runtime/src/fntrace.c @@ -63,7 +63,60 @@ static inline int armed_match(uint32_t target) { return 0; } +/* ── Stack-domain transition ring (ALWAYS-ON, every build) ───────────────── + * Records every dispatch where the guest SP crossed a 64 KB domain since the + * previous dispatch. Ordinary call nesting never moves SP that far, so the + * ring stays quiet except at genuine stack switches: game green-thread / + * coroutine context restores, longjmps, kernel thread changes, and crt0 + * stack (re)initialization. Those transitions are exactly the provenance + * question in stack-corruption deaths (Tomba 2 splash→title reload: the + * guest resumed on a stack pointing INTO freshly loaded module code, and + * nothing recorded who installed that SP). Cost: two loads + xor + branch + * per dispatch; entries only on domain edges. Dumped via `sp_ring`. */ +SpDomainEntry g_spdom_ring[SPDOM_RING_CAP]; +uint64_t g_spdom_seq = 0; +static uint32_t s_spdom_prev_sp = 0; + +/* Always-on dispatch tail ring: the last DISP_TAIL_CAP dispatches with + * target/ra/sp/cycle. Unlike the armed fntrace ring this is unconditional — + * sized tiny so the post-mortem question "what was the exact dispatch + * sequence in the final iterations" is always answerable (the Tomba 2 + * splash reload loop was invisible without it). Dumped via `disp_ring`. */ +DispTailEntry g_disp_tail[DISP_TAIL_CAP]; +uint64_t g_disp_tail_seq = 0; + void fntrace_record(CPUState* cpu, uint32_t target) { + { + extern uint64_t psx_get_cycle_count(void); + DispTailEntry *t = &g_disp_tail[g_disp_tail_seq % DISP_TAIL_CAP]; + t->target = target; + t->ra = cpu->gpr[31]; + t->sp = cpu->gpr[29]; + t->cycle = psx_get_cycle_count(); + g_disp_tail_seq++; + } + { + uint32_t sp_now = cpu->gpr[29]; + if (((sp_now ^ s_spdom_prev_sp) & 0xFFFF0000u) != 0u) { + if (s_spdom_prev_sp != 0u) { + extern uint64_t psx_get_cycle_count(void); + extern uint32_t psx_read_word(uint32_t addr); + SpDomainEntry *e = &g_spdom_ring[g_spdom_seq % SPDOM_RING_CAP]; + uint32_t pcb = psx_read_word(0x108u); + e->seq = g_spdom_seq; + e->cycle = psx_get_cycle_count(); + e->prev_sp = s_spdom_prev_sp; + e->new_sp = sp_now; + e->target = target; + e->ra = cpu->gpr[31]; + e->tcb = pcb ? psx_read_word(pcb & 0x1FFFFFFFu) : 0u; + e->frame = (uint32_t)s_frame_count; + g_spdom_seq++; + } + s_spdom_prev_sp = sp_now; + } + } + /* On-the-fly string translation (framework feature — text_xlate.cpp). The * generated psx_dispatch_impl calls us at the top of each dispatch iteration * with cpu->gpr[4..7] holding THIS call's args, BEFORE the target function diff --git a/runtime/src/overlay_loader.c b/runtime/src/overlay_loader.c index 8baab74d..13f20b7b 100644 --- a/runtime/src/overlay_loader.c +++ b/runtime/src/overlay_loader.c @@ -2957,7 +2957,10 @@ retry_candidates: #endif } if (_probe) s_cps_probe_outcome = 2; -#ifndef PSX_NO_DEBUG_TOOLS + /* Native-call ring: ALWAYS-ON (production too). Each entry names + * the requested PC and the candidate CRC that claimed it — the + * only record that can attribute a wrong-variant native run on + * a production binary (Tomba 2 splash reload loop). */ uint32_t slot = s_nring_pos++ & (NRING_CAP - 1u); s_nring[slot].addr = addr; s_nring[slot].crc = c->crc_code; @@ -2966,7 +2969,6 @@ retry_candidates: s_nring[slot].returned = 0; uint32_t prev_inprogress = s_native_inprogress; s_native_inprogress = c->addr; -#endif s_native_calls_total++; native_hot_note(c->addr); if (s_active_depth < (int)(sizeof(s_active_stack) / sizeof(s_active_stack[0]))) @@ -2983,10 +2985,8 @@ retry_candidates: } overlay_post_dispatch_irq_pump(cpu); if (s_active_depth > 0) s_active_depth--; -#ifndef PSX_NO_DEBUG_TOOLS s_nring[slot].returned = 1; s_native_inprogress = prev_inprogress; -#endif if (g_native_bad_entry) { /* foreign interior entry: fail closed to interp */ g_native_bad_entry = 0; s_disp_native--; s_disp_interp++; @@ -3098,7 +3098,7 @@ retry_candidates: /* Record into the always-on ring BEFORE the call; mark in-progress * so a freeze inside this fn is visible at dump time. */ -#ifndef PSX_NO_DEBUG_TOOLS + /* Native-call ring: ALWAYS-ON (see the range-chain site). */ uint32_t slot = s_nring_pos++ & (NRING_CAP - 1u); s_nring[slot].addr = c->addr; s_nring[slot].crc = c->crc_code; @@ -3107,7 +3107,6 @@ retry_candidates: s_nring[slot].returned = 0; uint32_t prev_inprogress = s_native_inprogress; s_native_inprogress = c->addr; -#endif s_native_calls_total++; native_hot_note(c->addr); @@ -3135,10 +3134,8 @@ retry_candidates: #endif if (s_active_depth > 0) s_active_depth--; -#ifndef PSX_NO_DEBUG_TOOLS s_nring[slot].returned = 1; s_native_inprogress = prev_inprogress; /* restore (nested calls) */ -#endif if (g_native_bad_entry) { /* foreign interior entry: fail closed to interp */ g_native_bad_entry = 0; s_disp_native--; s_disp_interp++;