From d9b6ae5e161db69ea962fbed237a12a4f084fc8b Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Wed, 17 Jun 2026 16:02:14 -0700 Subject: [PATCH] recursion: capture native_stack tooling + working doc Snapshot of the uncommitted native_stack capture tool (crash_trace.c, append_native_stack) that recovers the true compiled<->dirty-interp recursion cycle the recent_fn ring can't show, plus docs/RECURSION_BUG.md documenting the freeze root cause, the 4-instance soak reproduction harness, and the overworld-load regression now blocking repro. This is the build that currently insta-crashes soaks on overworld load; preserved as-is before hardening so the regression stays reproducible. Co-Authored-By: Claude Opus 4.8 --- docs/RECURSION_BUG.md | 169 ++++++++++++++++++++++++++++++++++++++ runtime/src/crash_trace.c | 129 +++++++++++++++++++++++++++++ 2 files changed, 298 insertions(+) create mode 100644 docs/RECURSION_BUG.md diff --git a/docs/RECURSION_BUG.md b/docs/RECURSION_BUG.md new file mode 100644 index 00000000..84c5ae96 --- /dev/null +++ b/docs/RECURSION_BUG.md @@ -0,0 +1,169 @@ +# Tomba long-run recursion freeze — working doc + +Branch: `bug/recursion`. This is the single source of truth for the long-run +freeze investigation and the soak-harness regression that is currently blocking +reproduction. Update it as we learn. + +--- + +## 1. The bug we are actually chasing (the freeze) + +**Symptom.** Tomba runs correctly for a long time, then hard-freezes. Intermittent; +*often sooner than 15 minutes* but **not reliable**. The captured specimen is +`_freeze_specimens/tomba_4393_freeze_46440.dmp` (frame 46440). + +**Root cause (from the minidump).** A **runaway guest recursion that never unwinds.** +The per-frame game-flow state machine re-enters *itself* across the +**compiled ↔ dirty-RAM-interpreter boundary**. Validated, symbolized cycle: + +``` +exec_one (main loop 0x8001A51C) + -> psx_dispatch_game_compiled(0x8001A954) + -> 0x8001A954 -> 0x8001AC00 -> 0x8001B2B4 -> 0x8001B5A8 -> 0x80046264 + -> dirty_ram_dispatch + -> psx_dispatch_game_compiled(0x8001A954) <-- back to the top +``` + +Repeats ~1443 times -> native **fiber stack overflows** -> stack-depth guard halts +the process (`psx_fatal_halt`, which parks or exits). The state-machine fields +`[+0x4a]/[+0x4c]/[+0x4e]` on the controller object at `0x801FD800` are pinned at +`1/1/1` and never advance — that is the cycle that won't terminate. The ~1443 +frames overflow nearly instantly *once the cycle starts*; the "~15m / intermittent" +is how long until the **trigger condition** is met, not how long the recursion runs. + +**What it is NOT** (all prior hypotheses, refuted): +- NOT data corruption — `0x8001a954` is not a wild pointer; it exists nowhere in + RAM as data. +- NOT nested interrupt delivery — `in_exception=0`, exception counts normal. +- NOT a fiber deadlock/livelock. +- Scene id intact, table `DAT_8007c640` intact. + +**Why it's slippery to capture.** `g_psx_dispatch_depth` reads only 5 — it is blind +to this, because the 1443 frames are direct `func_X(cpu)` calls it does not count. +The `recent_fn` ring is time-ordered, so it shows only the leaf churning at the trip, +**not** the recursing cycle. **This is the entire reason the native_stack tool +exists** (see §3). + +**Suspected trigger.** CD-DMA dirty-page over-marking: `dma.c:695` marks every +DMA'd word executable/dirty and never clears it (463/512 RAM pages dirty at the +freeze), time-correlated with the onset of boundary re-entry. + +**Fix territory (NOT yet done).** The interp<->compiled call/return contract +(`dirty_ram_dispatch` / `psx_dispatch_game_compiled`) must **unwind** at the +boundary instead of **nesting**; and/or stop `dma.c:695` marking non-code CD-DMA +data as executable/dirty. Same family as the "wild call contract" recursion bugs +(Bug A/C/D). The fix is in the **recompiler**, never in generated C. + +--- + +## 2. The reproduction harness ("soaks") — and the regression blocking it + +**Workflow.** Run **4 instances** in parallel ("Soak A/B/C/D"). Claude launches +them; the user navigates **2 to a New Game** and **2 into Dwarf Forest** (overworld), +then lets all four **idle**. Running 4x in parallel is how we hit the intermittent +freeze fast. Per-instance memcard dirs (`saves_a..d`), **software renderer**, 4:3, +ports 4393-4396 (`tomba_soak_{a,b,c,d}.toml`). Stay off heavy host work while +soaking (a wall-clock starvation watchdog, 4s no-heartbeat -> exit(2), false-trips +under host load). + +**The regression (currently blocking everything).** On the current +uncommitted/debug build, **Soaks A-D crash the instant anything loads to the +overworld** — before idle, before any chance to reproduce the freeze. SIGSEGV, +**no `psx_last_run_report.json`**. This did not happen on the build that used to +soak faithfully for ~15m. + +--- + +## 3. The native_stack tool (the thing that may be causing the regression) + +Uncommitted tooling added to `runtime/src/crash_trace.c` (129 lines): a +host-stack walker `append_native_stack()` that recovers the true recursion cycle +(the `recent_fn` ring can't — see §1). It is called **only** from +`psx_crash_trace_dump()`, i.e. only while a crash/fatal/SEH dump is already in +progress. It walks from the faulting/the current `rsp` up to the fiber `StackBase`, +keeps only validated return addresses (value in `.text` preceded by a `call`), +run-length-collapses them, and emits module-relative RVAs + a histogram. Every +stack read is bounded by `VirtualQuery`; symbolize offline with `nm` +(`_freeze_specimens/analyze_named.py`, `decode_report.py`). + +**Known hazard (handoff issue #3).** Both `psx_signal_handler` and +`psx_seh_handler` run **on the faulting stack** and call the dump. If the original +fault is the recursion's stack overflow, `append_native_stack` runs on the +already-exhausted stack and can **re-fault** — taking the whole report with it +(silent SIGSEGV, no JSON). As written, the tool meant to capture the overflow can +**destroy the very report it was built for.** + +--- + +## 4. Evidence collected this session (artifact-level) + +Compared `TombaRecomp/build-soak` (A, has tooling, crashes) vs +`TombaRecomp/build-soak-e` (B, pure master, healthy). MD5'd all 49 objects in each: +**only two differ** — `crash_trace.c.obj` and `main.cpp.obj`. `main.cpp` is an +AppImage `getenv("APPIMAGE")` change, **inert on Windows**. All generated BIOS/game +code (`SCUS_942.36_*.c.obj`, `SCPH1001_*.c.obj`) is **byte-identical MD5**. The +psxrecomp reflog shows HEAD parked at master `3ba40b0` since 09:34 that day, so A +and B were regen'd off the **same** master tip — **not** a flavor trap, **not** +stale generated code. (Those were the handoff's two hypotheses; both refuted.) + +**Open logical tension.** `crash_trace.c`'s only new code runs inside the dump +path, and **every dump caller terminates**. So if a dump fired on overworld-load, +build B (no tooling) would stop too — contradicting "B gets into game." Two ways +out, to be settled empirically (§5): +1. B was never actually driven through the exact "New Game -> overworld" path the + soaks use; OR +2. **the overworld-load regression is in `master` itself** (this morning's merges: + ws-backdrop-coverage @09:27, controller change @09:34), not the tooling. The A-vs-B + diff can't see a master regression because both A and B are post-09:34 master. + +--- + +## 5. Plan + +1. **(done)** Branch `bug/recursion`, write this down. +2. **Unravel the overworld-load regression — decisive A/B from source.** Build two + clean builds from current master: **X = master + native_stack tooling + + "flush report before the walk" hardening**; **Y = pure master, no tooling** + (the existing `build-soak-e` already IS Y). Run 2 soaks on X + 2 on Y, navigate + all to overworld: + - Y also crashes -> it's a **master regression**; bisect master against the + last-known-good faithful-soak commit. + - Only X crashes -> it's the **tooling**; X's report (now flushed before the + walk) shows the real trigger — recursion-fired-immediately vs a separate fault. + - X crashes with **no** report even after the early flush -> the fault is + **outside** `psx_crash_trace_dump` -> not `append_native_stack`; look elsewhere. +3. **Return to the soak workflow** on whichever build survives overworld-load, + reproduce the freeze, and capture it with native_stack (the early-flush makes the + report survive the overflow walk). +4. **Fix the recompiler** (interp<->compiled unwind contract and/or `dma.c:695` + over-marking). Regen, rebuild, re-soak to confirm. No stubs, no HLE, never edit + generated C. + +--- + +## 6. Build & run (this project) + +``` +cd /f/Projects/psxrecomp/TombaRecomp +export PATH=/c/msys64/mingw64/bin:$PATH TMP=/c/msys64/tmp TEMP=/c/msys64/tmp +# regen tools + BIOS + game (generated/ is gitignored; off master tip): +cmake --build ../psxrecomp/recompiler/build --target psxrecomp-game psxrecomp-bios -j8 +(cd ../psxrecomp && ./recompiler/build/psxrecomp-bios.exe --config bios/SCPH1001.toml) +../psxrecomp/recompiler/build/psxrecomp-game.exe --config tomba_soak_e.toml +# build: +cmake -S . -B -G Ninja -DCMAKE_BUILD_TYPE=Release -DPSX_DEBUG_TOOLS=ON -DPSX_LAUNCHER=OFF \ + -DCMAKE_C_COMPILER=C:/msys64/mingw64/bin/gcc.exe -DCMAKE_CXX_COMPILER=C:/msys64/mingw64/bin/g++.exe +cmake --build --target psx-runtime -j8 +# run (per-instance card; taskkill first): +taskkill //F //IM psx-runtime.exe 2>/dev/null +nohup .//psx-runtime.exe --game tomba_soak_a.toml > _soak_a.log 2>&1 & +# decode a freeze report's native_stack: +nm -n /psx-runtime.exe | awk '$2~/^[Tt]$/{print $1,$3}' > ../_freeze_specimens/allsyms.txt +python ../_freeze_specimens/decode_report.py psx_last_run_report.json ../_freeze_specimens/allsyms.txt +``` + +**Hard rules:** fix the recompiler, never generated C; no printf/log files (TCP +debug server + always-on rings; read `psx_last_run_report.json` for fatals); +per-instance memcard dir per concurrent instance (sharing corrupts the card -> +fake "regression"); software renderer for soaks; `taskkill //F //IM psx-runtime.exe` +before any launch. diff --git a/runtime/src/crash_trace.c b/runtime/src/crash_trace.c index 7fcc297e..6cb90e2e 100644 --- a/runtime/src/crash_trace.c +++ b/runtime/src/crash_trace.c @@ -21,6 +21,7 @@ #define WIN32_LEAN_AND_MEAN #define NOMINMAX #include +#include /* __readgsqword — fiber TEB stack bounds for native_stack walk */ #endif #include @@ -132,6 +133,123 @@ void psx_crash_trace_set_exit_origin(const char *origin) { if (origin) s_exit_origin = origin; } +/* ── Native call-stack snapshot ────────────────────────────────────────── + * + * The recent_fn ring is TIME-ORDERED (function entries over time), so for a + * runaway recursion its tail is dominated by whatever leaf was churning at the + * trip — it does NOT show the actual recursion CYCLE. This walks the running + * fiber's native stack at the fatal instant and recovers the true cycle: + * + * - Walk from the current/faulting RSP up to the fiber StackBase (TEB GS:[8]). + * - Keep only qwords that are genuine return addresses: a value pointing into + * this module's .text whose immediately-preceding bytes are a `call` + * instruction (filters spilled function pointers / stale data that merely + * look like code addresses). + * - Run-length-collapse consecutive equal frames and emit module-relative + * RVAs, plus a small frequency histogram (the recursion participants each + * appear ~depth times and dominate it). + * + * Emitted RVAs are build-relative (module base + RVA). Symbolize offline against + * the exact binary with nm (see _freeze_specimens/analyze_named.py, which reads + * this `native_stack` block directly). Works on BOTH the SEH path (uses the + * faulting ContextRecord->Rsp) and the graceful stack-guard halt path (walks the + * current frame), in debug and release — no minidump required. */ +#ifdef _WIN32 +static int crash_is_retaddr(uintptr_t v, uintptr_t text_lo, uintptr_t text_hi) { + if (v < text_lo + 7u || v >= text_hi) return 0; + const unsigned char *p = (const unsigned char *)(v - 7); + if (p[2] == 0xE8) return 1; /* call rel32 -> E8 at v-5 */ + unsigned char m = p[5]; /* byte at v-2 */ + if (p[4] == 0xFF && ((m >= 0xD0 && m <= 0xD7) || /* call reg */ + (m >= 0x10 && m <= 0x17))) /* call [reg] */ + return 1; + if (p[1] == 0xFF && p[2] == 0x15) return 1; /* call [rip+disp32] */ + if (p[3] == 0xFF && p[4] >= 0x50 && p[4] <= 0x57) /* call [reg+disp8] */ + return 1; + return 0; +} + +static void append_native_stack(char *buf, size_t cap, size_t *pos, uintptr_t start_sp) { + HMODULE h = GetModuleHandleW(NULL); + uintptr_t mb = (uintptr_t)h; + IMAGE_DOS_HEADER *dos = (IMAGE_DOS_HEADER *)h; + IMAGE_NT_HEADERS *nt = (IMAGE_NT_HEADERS *)((BYTE *)h + dos->e_lfanew); + IMAGE_SECTION_HEADER *sec = IMAGE_FIRST_SECTION(nt); + uintptr_t text_lo = 0, text_hi = 0; + for (int i = 0; i < nt->FileHeader.NumberOfSections; i++) { + if (!memcmp(sec[i].Name, ".text", 5)) { + text_lo = mb + sec[i].VirtualAddress; + text_hi = text_lo + sec[i].Misc.VirtualSize; + break; + } + } + uintptr_t base = (uintptr_t)__readgsqword(0x08); /* fiber StackBase (high) */ + char probe; + if (start_sp == 0) start_sp = (uintptr_t)&probe; + start_sp &= ~(uintptr_t)7; + + append_fmt(buf, cap, pos, + " \"native_stack\": {\n" + " \"module_base\": \"0x%llX\",\n" + " \"text_lo_rva\": \"0x%llX\",\n" + " \"text_hi_rva\": \"0x%llX\",\n" + " \"frames\": [", + (unsigned long long)mb, + (unsigned long long)(text_lo - mb), + (unsigned long long)(text_hi - mb)); + + enum { HCAP = 24, MAX_RUNS = 256 }; + uint32_t hk[HCAP]; uint32_t hc[HCAP]; int hn = 0; + uint32_t prev_rva = 0; int run = 0, emitted = 0, total = 0; + + /* This runs in the crash/halt path, so it MUST never fault: bound every + * read with VirtualQuery and stop at the first non-committed / non-readable + * page or the PAGE_GUARD page (touching it would re-arm the overflow). The + * fiber StackBase (base) is only a hint — if it's stale/bogus the region + * walk terminates safely at the real committed-stack top anyway. */ + if (text_lo && start_sp) { + MEMORY_BASIC_INFORMATION mbi; + uintptr_t region_end = 0; + for (uintptr_t a = start_sp; total < 300000; a += 8) { + if (base > start_sp && a + 8 > base) break; /* don't pass a good StackBase */ + if (a + 8 > region_end) { /* (re)validate the page region */ + if (!VirtualQuery((void *)a, &mbi, sizeof(mbi))) break; + if (!(mbi.State & MEM_COMMIT)) break; + if (mbi.Protect & PAGE_GUARD) break; + DWORD pr = mbi.Protect & 0xFFu; + if (!(pr & (PAGE_READONLY | PAGE_READWRITE | PAGE_WRITECOPY | + PAGE_EXECUTE_READ | PAGE_EXECUTE_READWRITE | PAGE_EXECUTE_WRITECOPY))) + break; + region_end = (uintptr_t)mbi.BaseAddress + mbi.RegionSize; + } + uintptr_t v = *(uintptr_t *)a; + if (!crash_is_retaddr(v, text_lo, text_hi)) continue; + uint32_t rva = (uint32_t)(v - mb); + total++; + int found = 0; + for (int k = 0; k < hn; k++) { if (hk[k] == rva) { hc[k]++; found = 1; break; } } + if (!found && hn < HCAP) { hk[hn] = rva; hc[hn] = 1; hn++; } + if (total > 1 && rva == prev_rva) { run++; continue; } + if (run > 0 && emitted < MAX_RUNS) { + append_fmt(buf, cap, pos, "%s{\"rva\":\"0x%X\",\"n\":%d}", + emitted ? "," : "", prev_rva, run); + emitted++; + } + prev_rva = rva; run = 1; + } + if (run > 0 && emitted < MAX_RUNS) + append_fmt(buf, cap, pos, "%s{\"rva\":\"0x%X\",\"n\":%d}", + emitted ? "," : "", prev_rva, run); + } + append_fmt(buf, cap, pos, + "],\n \"total_frames\": %d,\n \"runs_emitted\": %d,\n \"histogram\": [", + total, emitted); + for (int k = 0; k < hn; k++) + append_fmt(buf, cap, pos, "%s{\"rva\":\"0x%X\",\"n\":%u}", k ? "," : "", hk[k], hc[k]); + append_str(buf, cap, pos, "]\n },\n"); +} +#endif /* _WIN32 */ + /* ── Main entry ──────────────────────────────────────────────────────── */ void psx_crash_trace_dump(const char *reason, void *seh_info) { @@ -291,6 +409,17 @@ void psx_crash_trace_dump(const char *reason, void *seh_info) { append_str(buf, sizeof(buf), &pos, "]\n },\n"); } + /* Native call-stack snapshot — the TRUE recursion cycle (recent_fn above is + * time-ordered and shows leaf churn, not the recursing frames). */ +#ifdef _WIN32 + { + uintptr_t sp = 0; + if (seh_info) + sp = (uintptr_t)((EXCEPTION_POINTERS *)seh_info)->ContextRecord->Rsp; + append_native_stack(buf, sizeof(buf), &pos, sp); + } +#endif + /* dispatch_ring tail (last 256) */ { uint64_t total = crash_trace_dispatch_seq_get();