Commit Graph

2 Commits

Author SHA1 Message Date
Matthew Stanley ffc15219fd fix: Bug B hard freeze — TOCTOU underflow in frame pacing slept ~24.7 days
Root cause (freeze dump 1781046069, addr2line-verified): the wall-clock
pacing loop in sdl_vblank_present read the performance counter twice per
iteration — once in the while-condition, once to compute remaining time.
If the frame deadline was crossed between the two reads (a preemption
window), the unsigned subtraction underflowed, *1000 overflowed, and
SDL_Delay received ~2^64/10^4 ms mod 2^32 ≈ 24.7 days at the standard
10 MHz QPC. The app parks in one SDL_Delay with every counter frozen,
wedged between 'i_stat |= VBLANK' (interrupts.c:286) and exception
delivery — which is why dumps showed i_stat=1 pinned. VBLANK was being
ACK'd every frame right up to the wedge in every dump examined; the
'VBLANK-ACK reentry storm' framing was a symptom misread.

- frame_pacing.c/h: shared race-free pacer (single counter read per
  decision, compare-before-subtract, sleep clamped to one period).
  Both call sites switched: main.cpp sdl_vblank_present and
  beetle_main.cpp. Unit test pins the underflow case.
- Vsync self-heal: the 'recovered storm' dump (1781045865) was 8/8
  main-thread samples inside wglSwapBuffers — NV driver blocking ~1.5s
  per present. After 3 presents >250ms, drop driver vsync (we pace to
  59.94 Hz ourselves). Counters surfaced in the freeze dump.
- Watchdog classifier: 'reentry_storm' threshold (5K/sec) was below the
  healthy baseline (~2K reentry blocks/frame × 30-60 fps), mislabeling
  normal play and host stalls — that label misdirected two prior
  investigations. Now normalized per frame (>20K/frame), plus a new
  slow_frames kind (<5 fps) with multi-sample stack capture.

Verified: test_frame_pacing ALL PASS; live Tomba paced at 59.962 fps
over 20s (single-process measurement).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-06-09 20:09:25 -07:00
Matthew Stanley 5b3c7dd08d phase4: freeze_check diagnostic + accumulated overnight infra
Today's session work
- runtime/src/debug_server.c: freeze_check TCP cmd snapshots all liveness
  counters (PC, exception entries, exception_reentry_blocks, dirty_ram
  blocks/insns, fn_entry total + top-K histogram, SIO IRQ pending +
  countdown, sio_stat/i_stat/i_mask, mc_max_state) for tight-loop
  diagnosis when the runtime hangs
- runtime/src/debug_server.c: wtrace slot 12 covering [0x72F0..0x72F4]
  (data-byte counter); measured peak=1 confirming setup_data_phase resets
  the counter mid-cycle
- runtime/src/interrupts.c: exception_entries_total + exception_reentry_blocks
  counters + psx_get_freeze_diag accessor
- runtime/src/sio.c: sio_get_freeze_diag accessor for IRQ pacing internals
- memory entries: phase4_card_gate_setup_writes_2026_04_28 (refutes the
  prior \"missing [0x7568+slot] clearer\" framing — setup functions write
  LSB=0 directly), phase4_72f0_one_byte_per_vblank_2026_04_28 (peak=1
  measurement)

Overnight session work bundled in
- runtime/src/dirty_ram_interp.{c,h}: small MIPS interpreter for
  install-at-runtime kernel RAM stubs (Rule 18; e.g., SIO data-byte
  handler the BIOS writes to RAM 0xCF0)
- recompiler/src/full_function_emitter.{cpp,h}: 3057 jal/jalr continuation
  return labels added to dispatch table (continuation fix); branch
  fall-through fix for conditional-branch delay slots
- recompiler/src/strict_translator.cpp: matching translator updates
- generated/: regenerated SCPH1001 dispatch + full C output reflecting
  the recompiler changes
- runtime/include/debug_server.h, src/memory.c: card_txn ring + SIO IRQ
  ring + EvCB walk ring + per-PC dirty_ram counters + always-on wtrace
  coverage for [0x755A], [0x7514], [0x7528], [0x7520], [0x74A4],
  [0x75C0..C8], [0x74B8..C0]
- recompiler/tests/, runtime/tests/: SIO/card protocol unit tests
- tools/: 60+ Python diagnostic scripts (chain_trace analysis, SIO trace
  diff, EvCB walker, wtrace dumpers, etc.)
- docs/: psx_bios_disasm reference + dynamic_handler_install rationale
- OVERNIGHT_2026_04_28.md, SUMMARY_20260412_2.md: session logs

Phase 4 status (still blocked, root cause better understood)
- BIOS card chain runs through R-handlers correctly (chain_trace shows
  R1..R11 cycling 26x); shell IS retriggering _card_read
- Install handler at ROM 0xBFC15F1C increments [0x72F0] correctly per
  SIO IRQ; gate at <0x80 / <0x7F is correct
- Bottleneck: SIO IRQ countdown is access-paced, fires ~1× per VBlank
  vs ~128× needed; setup_data_phase (called from outer coord on VBlank)
  zeroes [0x72F0] before counter reaches 128
- Both attempted fixes today caused freezes:
  * VBlank deferral on [0x75C0]==1 — pending VBlank already in i_stat
    delivered anyway; tighter dispatch gate also locked up
  * Cycle-paced sio_tick at rates 50, 200 (and gated on [0x75C0]==1) —
    runtime freezes once data phase activates, root cause unidentified
- delay=5 narrows the threshold (peak=2 vs peak=1, no freeze) but
  doesn't get to 0x80
- Real fix likely requires deeper instrumentation of the freeze (call
  stack / dispatch state at the moment of TCP starvation)

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-28 21:29:19 -07:00