diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index db912f99..77bb4d0e 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -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} ) diff --git a/runtime/include/frame_pacing.h b/runtime/include/frame_pacing.h new file mode 100644 index 00000000..b3c581e8 --- /dev/null +++ b/runtime/include/frame_pacing.h @@ -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 + +#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 */ diff --git a/runtime/runtime.cmake b/runtime/runtime.cmake index e73e07e8..2bb63f87 100644 --- a/runtime/runtime.cmake +++ b/runtime/runtime.cmake @@ -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 diff --git a/runtime/src/beetle_main.cpp b/runtime/src/beetle_main.cpp index 84fc2ea2..f8c163b8 100644 --- a/runtime/src/beetle_main.cpp +++ b/runtime/src/beetle_main.cpp @@ -3,6 +3,7 @@ * Beetle's framebuffer, keyboard input, TCP debug server on port 4380. */ #include +#include "frame_pacing.h" #include #include #include @@ -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); } } diff --git a/runtime/src/frame_pacing.c b/runtime/src/frame_pacing.c new file mode 100644 index 00000000..95f9c2e8 --- /dev/null +++ b/runtime/src/frame_pacing.c @@ -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 +#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 */ diff --git a/runtime/src/freeze_heartbeat.c b/runtime/src/freeze_heartbeat.c index 515d5dc3..0ac862f2 100644 --- a/runtime/src/freeze_heartbeat.c +++ b/runtime/src/freeze_heartbeat.c @@ -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) { diff --git a/runtime/src/main.cpp b/runtime/src/main.cpp index bed8f5ba..10d0c95f 100644 --- a/runtime/src/main.cpp +++ b/runtime/src/main.cpp @@ -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 } diff --git a/runtime/tests/test_frame_pacing.c b/runtime/tests/test_frame_pacing.c new file mode 100644 index 00000000..bf053ffb --- /dev/null +++ b/runtime/tests/test_frame_pacing.c @@ -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 +#include + +/* 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; +}