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>
This commit is contained in:
Matthew Stanley
2026-06-09 20:09:25 -07:00
parent 03b4f31893
commit ffc15219fd
8 changed files with 269 additions and 61 deletions
+1
View File
@@ -77,6 +77,7 @@ if(NOT MSVC AND EXISTS "${BEETLE_LIB}")
src/beetle_main.cpp
src/beetle_libretro.cpp
src/beetle_debug_server.c
src/frame_pacing.c
${LIBRETRO_COMMON_SOURCES}
)
+52
View File
@@ -0,0 +1,52 @@
/*
* frame_pacing.h — race-free wall-clock frame pacing.
*
* Replaces the open-coded pacing loops in main.cpp (sdl_vblank_present)
* and beetle_main.cpp. The open-coded version read the performance
* counter twice per iteration (once in the while-condition, once to
* compute the remaining time); if the deadline was crossed between the
* two reads — a preemption-sized window — the unsigned subtraction
* underflowed and SDL_Delay received a ~24.7-day argument (2^64 ticks
* * 1000 / 10 MHz, truncated to Uint32). That was the Bug B hard
* freeze: the app parks in one SDL_Delay with every counter frozen,
* wedged between `i_stat |= VBLANK` and exception delivery.
*
* Rules the implementation must keep:
* - exactly ONE counter read per decision; compare before subtract
* - the computed sleep is clamped to one frame period
* - a deadline already in the past never sleeps
*/
#ifndef FRAME_PACING_H
#define FRAME_PACING_H
#include <stdint.h>
#ifdef __cplusplus
extern "C" {
#endif
typedef struct FramePacer {
uint64_t next_deadline; /* perf-counter ticks; 0 = not started */
} FramePacer;
/* Pure decision function (unit-testable, no SDL).
* Given a single counter sample `now`, the current deadline, the counter
* frequency and the frame period (both in ticks), returns the number of
* milliseconds to sleep right now, or 0 if the caller should stop
* sleeping (deadline reached / close enough to spin).
* Never returns a value larger than one period's worth of ms + 1. */
uint32_t frame_pacing_sleep_ms(uint64_t now, uint64_t deadline,
uint64_t freq, uint64_t period);
/* Block until the pacer's next deadline (sleep + final sub-ms spin),
* then advance the deadline by one period. If the pacer has not
* started, or the caller fell more than one period behind, re-anchors
* to now + period without sleeping. period_ms is the frame period in
* milliseconds (e.g. 1000.0 / 59.94). */
void frame_pacer_wait(FramePacer *p, double period_ms);
#ifdef __cplusplus
}
#endif
#endif /* FRAME_PACING_H */
+1
View File
@@ -72,6 +72,7 @@ set(PSXRECOMP_RUNTIME_SOURCES
${PSXRECOMP_ROOT}/runtime/src/mdec.c
${PSXRECOMP_ROOT}/runtime/src/timers.c
${PSXRECOMP_ROOT}/runtime/src/interrupts.c
${PSXRECOMP_ROOT}/runtime/src/frame_pacing.c
${PSXRECOMP_ROOT}/runtime/src/psx_fiber.c
${PSXRECOMP_ROOT}/runtime/src/sio.c
${PSXRECOMP_ROOT}/runtime/src/memcard.c
+3 -16
View File
@@ -3,6 +3,7 @@
* Beetle's framebuffer, keyboard input, TCP debug server on port 4380. */
#include <SDL.h>
#include "frame_pacing.h"
#include <cstdio>
#include <cstring>
#include <cstdlib>
@@ -170,21 +171,7 @@ int main(int argc, char** argv) {
const Uint8* keys = SDL_GetKeyboardState(NULL);
if (keys && keys[SDL_SCANCODE_TAB]) continue;
constexpr double FRAME_MS = 1000.0 / 59.94;
static Uint64 deadline = 0;
Uint64 freq = SDL_GetPerformanceFrequency();
Uint64 period = (Uint64)((double)freq * (FRAME_MS / 1000.0));
Uint64 now = SDL_GetPerformanceCounter();
if (deadline == 0 || now >= deadline + period) {
deadline = now + period;
} else {
while (SDL_GetPerformanceCounter() < deadline) {
Uint64 left = deadline - SDL_GetPerformanceCounter();
Uint64 ms = (left * 1000) / freq;
if (ms >= 2) SDL_Delay((Uint32)(ms - 1));
else break;
}
while (SDL_GetPerformanceCounter() < deadline) { /* spin */ }
deadline += period;
}
static FramePacer pacer = { 0 };
frame_pacer_wait(&pacer, FRAME_MS);
}
}
+48
View File
@@ -0,0 +1,48 @@
/*
* frame_pacing.c — race-free wall-clock frame pacing.
* See frame_pacing.h for the Bug B history this replaces.
*/
#include "frame_pacing.h"
/* FRAME_PACING_PURE_ONLY: tests compile only the SDL-free decision
* function (tests/test_frame_pacing.c includes this file directly). */
#ifndef FRAME_PACING_PURE_ONLY
#include <SDL.h>
#endif
uint32_t frame_pacing_sleep_ms(uint64_t now, uint64_t deadline,
uint64_t freq, uint64_t period) {
if (now >= deadline) return 0; /* compare BEFORE subtract */
uint64_t remaining = deadline - now; /* cannot underflow */
if (remaining > period) remaining = period;/* hard cap: one frame max */
if (freq == 0) return 0;
/* remaining <= period (~one frame of ticks), so *1000 cannot overflow. */
uint64_t ms = (remaining * 1000u) / freq;
if (ms < 2) return 0; /* sub-2ms: spin instead */
return (uint32_t)(ms - 1); /* undershoot; spin covers rest */
}
#ifndef FRAME_PACING_PURE_ONLY
void frame_pacer_wait(FramePacer *p, double period_ms) {
uint64_t freq = SDL_GetPerformanceFrequency();
uint64_t period = (uint64_t)((double)freq * (period_ms / 1000.0));
uint64_t now = SDL_GetPerformanceCounter();
if (p->next_deadline == 0 || now >= p->next_deadline + period) {
/* First frame, or fell more than one period behind: re-anchor. */
p->next_deadline = now + period;
return;
}
for (;;) {
now = SDL_GetPerformanceCounter(); /* ONE read per iteration */
uint32_t ms = frame_pacing_sleep_ms(now, p->next_deadline, freq, period);
if (ms == 0) break;
SDL_Delay(ms);
}
while (SDL_GetPerformanceCounter() < p->next_deadline) {
/* final sub-ms spin */
}
p->next_deadline += period;
}
#endif /* FRAME_PACING_PURE_ONLY */
+47 -21
View File
@@ -40,6 +40,12 @@ extern int sio_get_tx_writes(void);
extern uint64_t g_dirty_ram_blocks_run;
extern uint64_t g_dirty_ram_insns_run;
/* Vsync self-heal counters — defined in main.cpp. Included in the dump
* so a slow_frames wedge can be attributed to driver present
* backpressure straight from the JSON. */
extern uint32_t g_present_slow_count;
extern int g_present_vsync_disabled;
static int s_started = 0;
static char s_backend[32] = "psx-runtime";
@@ -55,20 +61,33 @@ static int s_sym_initialized = 0;
/* Wedge detection.
*
* Two failure modes to catch:
* Three failure modes to catch:
* A. HARD freeze — main thread is fully wedged; frame_count stops
* advancing entirely. Detected by zero frame_delta over the window.
* B. SOFT freeze / reentry storm — frame_count keeps advancing
* (sometimes at near-normal rate) but the main thread is starved
* by exception-handler reentry. Detected by exc_reentry_blocks
* delta exceeding a threshold over the window. OPTIONS-black on
* psx-runtime is this case: ~58 Hz frame rate, ~45K reentries/sec.
* (Bug B root cause was this kind: the old pacing loop's double
* counter read underflowed into a ~24.7-day SDL_Delay.)
* B. REENTRY storm — frames advance but exception-handler reentry
* per frame is far above the chronic baseline. The baseline is
* ~2K reentry blocks per frame (the whole VSync callback chain
* runs in exception context, every block leader checks), so the
* storm test must be normalized PER FRAME, not per second. The
* old absolute threshold (10K per 2s window = 5K/sec) was below
* the healthy baseline (~2K/frame x 30-60 fps = 60-120K/sec) and
* labeled normal play, boots, and host-side slowdowns all as
* "reentry_storm" — which twice sent freeze investigations down
* the wrong path.
* C. SLOW frames — frames advance but pathologically slowly while
* per-frame PSX work is normal: the wall clock is being eaten
* outside the simulation (observed: NVIDIA GL SwapBuffers
* blocking ~1.5s per present, dump 1781045865). Multi-sample
* stack capture attributes the wait.
*
* Window = 20 ticks = 2.0 sec. Long enough that legitimate startup
* activity (boot, FMV decode, save load) doesn't trip it; short enough
* that real wedges dump within seconds. */
#define WEDGE_WINDOW_TICKS 20u
#define WEDGE_EXC_REENTRY_DELTA_THRESHOLD 10000u /* >5K/sec sustained = wedge */
#define WEDGE_EXC_REENTRY_PER_FRAME_THRESHOLD 20000u /* ~10x chronic 2K/frame */
#define WEDGE_SLOW_FRAMES_MAX_DELTA 10u /* <5 fps avg over the 2s window */
/* Per-ring caps for auto-dump. Newest-first window. Sized so the total
* dump fits in ~10-15 MB JSON even when every ring is full. */
@@ -217,7 +236,7 @@ static void freeze_dump_main_stack_json(FILE *f) {
ResumeThread(s_main_thread);
}
/* Multi-sample stack capture for SOFT/reentry-storm freezes (wedge_kind==2).
/* Multi-sample stack capture for still-running wedges (wedge_kind 2 and 3).
* The main thread is still running (bouncing through the exception/VSync
* dispatch), so a single snapshot could land on a random recompiled block.
* Taking N snapshots a few ms apart reveals the RECURRING frames (the
@@ -277,6 +296,8 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc,
" \"tx_writes\":%d,\n"
" \"dirty_ram_blocks\":%llu,\n"
" \"dirty_ram_insns\":%llu,\n"
" \"present_slow_count\":%u,\n"
" \"present_vsync_disabled\":%d,\n"
" \"wedge_kind\":%u,\n"
" \"wedge_kind_name\":\"%s\",\n"
" \"caps\":{\"wtrace_all\":%u,\"wtrace\":%u,\"frames\":%u,"
@@ -295,9 +316,12 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc,
mc_max, tx_writes,
(unsigned long long)g_dirty_ram_blocks_run,
(unsigned long long)g_dirty_ram_insns_run,
g_present_slow_count,
g_present_vsync_disabled,
s_last_wedge_kind,
(s_last_wedge_kind == 1) ? "hard_freeze" :
(s_last_wedge_kind == 2) ? "reentry_storm" : "unknown",
(s_last_wedge_kind == 2) ? "reentry_storm" :
(s_last_wedge_kind == 3) ? "slow_frames" : "unknown",
(unsigned)DUMP_CAP_WTRACE_ALL,
(unsigned)DUMP_CAP_WTRACE,
(unsigned)DUMP_CAP_FRAME_HISTORY,
@@ -364,11 +388,10 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc,
#ifdef _WIN32
/* Main-thread call stack. Hard freeze (wedge_kind==1): one snapshot of the
* wedged thread in `main_stack`. Reentry storm (wedge_kind==2): the thread
* is still running, so a single frame is noise — take multiple samples in
* `main_stack_samples` to expose the recurring exception/VSync dispatch
* chain. (This freeze isn't reliably reproducible, so we capture the most
* useful possible stack whenever it does fire.) */
* wedged thread in `main_stack`. Still-running wedges (kind 2 reentry
* storm, kind 3 slow frames): a single frame is noise — take multiple
* samples in `main_stack_samples` to expose the recurring wait (the
* dispatch/handler chain, or a driver present block). */
fputs(" \"main_stack\":", f);
if (s_last_wedge_kind == 1) {
freeze_dump_main_stack_json(f);
@@ -376,7 +399,7 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc,
fputs("[]", f);
}
fputs(",\n \"main_stack_samples\":", f);
if (s_last_wedge_kind == 2) {
if (s_last_wedge_kind == 2 || s_last_wedge_kind == 3) {
freeze_dump_main_stack_samples_json(f, 8);
} else {
fputs("[]", f);
@@ -441,13 +464,14 @@ static void heartbeat_write(void) {
/* ---- Wedge detection: arm-once auto-dump ----
* Walk back WEDGE_WINDOW_TICKS in the heartbeat ring (just pushed
* above) and compute deltas. Trigger if either:
* A. frame_count delta == 0 (hard freeze)
* B. exc_reentry delta > threshold (reentry storm; soft freeze)
* above) and compute deltas. Trigger if any of:
* A. frame_count delta == 0 (hard freeze)
* B. exc_reentry delta PER FRAME > threshold (reentry storm)
* C. frame_count delta < slow-frames floor (host-side stall)
*
* Only fires once the ring has enough history. When the wedge clears
* (a healthy tick: frames advancing AND exc_re quiet), re-arm. */
uint32_t wedge_kind = 0; /* 0=healthy, 1=hard freeze, 2=reentry storm */
* (a healthy tick), re-arm. */
uint32_t wedge_kind = 0; /* 0=healthy 1=hard 2=reentry storm 3=slow frames */
if (s_ring_count >= WEDGE_WINDOW_TICKS) {
/* The just-pushed tick is at (s_ring_head - 1). The oldest in
* our window is WEDGE_WINDOW_TICKS - 1 ticks before it. */
@@ -464,8 +488,10 @@ static void heartbeat_write(void) {
if (frame_delta == 0)
wedge_kind = 1;
else if (excre_delta > WEDGE_EXC_REENTRY_DELTA_THRESHOLD)
else if (excre_delta / frame_delta > WEDGE_EXC_REENTRY_PER_FRAME_THRESHOLD)
wedge_kind = 2;
else if (frame_delta < WEDGE_SLOW_FRAMES_MAX_DELTA)
wedge_kind = 3;
}
if (wedge_kind != 0) {
+40 -24
View File
@@ -14,6 +14,7 @@
#include "overlay_loader.h"
#include "autocompile.h"
#include "gpu.h"
#include "frame_pacing.h"
#include "sio.h"
#include "spu.h"
#include "memcard.h"
@@ -91,6 +92,15 @@ static SDL_JoystickID sdl_controller_instance = -1;
static uint32_t sdl_pixel_buf[640 * 512]; /* ARGB8888 staging buffer */
static int s_fast_boot_active = 0; /* cleared when game entry PC fires */
/* Vsync self-heal state (see SDL_RenderPresent wrapper in
* sdl_vblank_present). C linkage: freeze_heartbeat.c includes both in
* the freeze dump so a slow-frames wedge can be attributed to driver
* present backpressure from the dump alone. */
extern "C" {
uint32_t g_present_slow_count = 0; /* presents that blocked >250ms */
int g_present_vsync_disabled = 0; /* 1 once self-heal tripped */
}
/* Turbo-through-loads (step 4). C linkage: debug_server.c reads/toggles the
* enable and reports the frame counter. Enabled by game.toml [runtime]
* turbo_loads (opt-in per game) or the turbo_loads TCP command. */
@@ -1011,30 +1021,13 @@ static void sdl_vblank_present(void) {
/* Wall-clock pacing: always runs once fast_boot has ended, even when the
* display is still disabled (e.g. game crt0 setup). Skipped only by the
* turbo and fast_boot early-returns above. */
* turbo and fast_boot early-returns above. frame_pacer_wait is the
* race-free replacement for the old open-coded loop whose double
* counter read could underflow into a ~24.7-day SDL_Delay (Bug B
* hard freeze). */
{
static Uint64 next_deadline = 0;
Uint64 freq = SDL_GetPerformanceFrequency();
Uint64 period = (Uint64)((double)freq * (PSX_FRAME_PERIOD_MS / 1000.0));
Uint64 now = SDL_GetPerformanceCounter();
if (next_deadline == 0 || now >= next_deadline + period) {
next_deadline = now + period; /* first frame, or fell behind */
} else {
while (SDL_GetPerformanceCounter() < next_deadline) {
Uint64 remaining_ticks = next_deadline - SDL_GetPerformanceCounter();
Uint64 remaining_ms = (remaining_ticks * 1000) / freq;
if (remaining_ms >= 2) {
SDL_Delay((Uint32)(remaining_ms - 1));
} else {
/* Final spin for sub-ms accuracy. */
break;
}
}
while (SDL_GetPerformanceCounter() < next_deadline) {
/* spin */
}
next_deadline += period;
}
static FramePacer pacer = { 0 };
frame_pacer_wait(&pacer, PSX_FRAME_PERIOD_MS);
}
/* ---- Display from our VRAM ---- */
@@ -1074,7 +1067,30 @@ static void sdl_vblank_present(void) {
SDL_Rect dst = { 0, 0, 640, 480 };
SDL_RenderClear(sdl_renderer);
SDL_RenderCopy(sdl_renderer, sdl_texture, &src, &dst);
SDL_RenderPresent(sdl_renderer);
/* Vsync self-heal. The renderer is created with PRESENTVSYNC for
* tear-free output, but the wall-clock pacer above already holds
* 59.94 Hz, so driver vsync is redundant for timing. Under some
* driver states (observed: NVIDIA GL with the swap queue wedged)
* SwapBuffers blocks ~1.5 s per present, dragging the whole
* emulation to ~0.7 fps for minutes (freeze dump 1781045865:
* 8/8 main-thread samples inside wglSwapBuffers). If presents
* block pathologically several times in a row, drop driver vsync
* for the rest of the session; our own pacing keeps the rate. */
{
const Uint64 t0 = SDL_GetPerformanceCounter();
SDL_RenderPresent(sdl_renderer);
const Uint64 t1 = SDL_GetPerformanceCounter();
const Uint64 freq = SDL_GetPerformanceFrequency();
const Uint64 present_ms = (t1 >= t0 && freq) ? ((t1 - t0) * 1000u) / freq : 0;
if (!g_present_vsync_disabled && present_ms > 250) {
g_present_slow_count++;
if (g_present_slow_count >= 3 &&
SDL_RenderSetVSync(sdl_renderer, 0) == 0) {
g_present_vsync_disabled = 1;
}
}
}
#endif
}
+77
View File
@@ -0,0 +1,77 @@
/*
* test_frame_pacing.c — validate the race-free pacing decision function.
*
* Bug B regression test. The old open-coded pacing loop in
* sdl_vblank_present read the performance counter twice: once in the
* while-condition, once to compute remaining time. If the deadline was
* crossed between the two reads, the unsigned subtraction underflowed
* and SDL_Delay received (2^64 - delta_ticks)*1000/freq truncated to
* Uint32 — ~24.7 days at the standard 10 MHz QPC. The replacement,
* frame_pacing_sleep_ms(), takes a SINGLE counter sample and compares
* before subtracting, so the underflow is impossible by construction.
* This test pins that property, including the exact post-deadline
* sample that froze the app.
*
* Build: gcc -I../include -o test_frame_pacing test_frame_pacing.c
* (includes ../src/frame_pacing.c directly with FRAME_PACING_PURE_ONLY,
* which compiles only the SDL-free decision function.)
*/
#include <stdio.h>
#include <stdint.h>
/* Pull in just the pure function — frame_pacing.c guards its SDL parts. */
#define FRAME_PACING_PURE_ONLY 1
#include "../src/frame_pacing.c"
static int failures = 0;
#define CHECK(cond, msg) do { \
if (!(cond)) { printf("FAIL: %s\n", msg); failures++; } \
else { printf("ok: %s\n", msg); } \
} while (0)
int main(void) {
const uint64_t FREQ = 10000000ull; /* standard Win10 QPC: 10 MHz */
const uint64_t PERIOD = (uint64_t)((double)FREQ * (1000.0 / 59.94) / 1000.0);
/* 1. The Bug B scenario: counter sampled just AFTER the deadline
* (old code underflowed here -> ~24.7-day sleep). Must be 0. */
uint64_t deadline = 1000000000ull;
CHECK(frame_pacing_sleep_ms(deadline + 1, deadline, FREQ, PERIOD) == 0,
"now just past deadline sleeps 0 (Bug B underflow case)");
CHECK(frame_pacing_sleep_ms(deadline + 123456789ull, deadline, FREQ, PERIOD) == 0,
"now far past deadline sleeps 0");
CHECK(frame_pacing_sleep_ms(deadline, deadline, FREQ, PERIOD) == 0,
"now exactly at deadline sleeps 0");
/* 2. Normal case: ~10ms remaining -> sleep 9ms (1ms undershoot for spin). */
CHECK(frame_pacing_sleep_ms(deadline - FREQ / 100, deadline, FREQ, PERIOD) == 9,
"10ms remaining sleeps 9ms");
/* 3. Sub-2ms remaining -> 0 (caller spins). */
CHECK(frame_pacing_sleep_ms(deadline - FREQ / 1000, deadline, FREQ, PERIOD) == 0,
"1ms remaining spins (0)");
/* 4. Deadline absurdly far ahead (corrupt/poisoned state) -> clamped to
* one period, never a multi-day sleep. */
uint32_t ms = frame_pacing_sleep_ms(0, UINT64_MAX, FREQ, PERIOD);
CHECK(ms <= (PERIOD * 1000 / FREQ),
"runaway deadline clamped to <= one period");
/* 5. freq == 0 (degenerate platform answer) -> 0, no divide-by-zero. */
CHECK(frame_pacing_sleep_ms(deadline - FREQ / 100, deadline, 0, PERIOD) == 0,
"freq 0 returns 0");
/* 6. Sweep the deadline-crossing window tick by tick: result must be
* monotonically sane and never exceed one period's ms. This is the
* exact window the old TOCTOU race made lethal. */
int sweep_ok = 1;
for (int64_t d = -20; d <= 20; d++) {
uint64_t now = deadline + (uint64_t)d; /* wraps safely for d<0 */
uint32_t v = frame_pacing_sleep_ms(now, deadline, FREQ, PERIOD);
if (v > (PERIOD * 1000 / FREQ) + 1) { sweep_ok = 0; break; }
}
CHECK(sweep_ok, "tick-by-tick sweep across deadline never exceeds one period");
printf(failures ? "FAILED (%d)\n" : "ALL PASS\n", failures);
return failures ? 1 : 0;
}