From 22f12a54f75efba467b1334b87154a4e931726cd Mon Sep 17 00:00:00 2001 From: Shokunin <30949000+tetrisgm@users.noreply.github.com> Date: Wed, 21 Oct 2026 09:09:26 -0700 Subject: [PATCH] Exclude host waits from render-thread GPU timing brackets --- docs/internal/FAITHFUL_TIMING_PLAN.md | 2 + runtime/include/render_thread.h | 3 ++ runtime/src/gpu_gl_renderer.c | 65 ++++++++++++++++++++------- runtime/src/render_thread.c | 3 ++ runtime/tests/run_gl_render_thread.py | 5 +++ runtime/tests/test_gl_render_thread.c | 18 ++++++++ 6 files changed, 80 insertions(+), 16 deletions(-) diff --git a/docs/internal/FAITHFUL_TIMING_PLAN.md b/docs/internal/FAITHFUL_TIMING_PLAN.md index 41cf9d5c..ecc681ca 100644 --- a/docs/internal/FAITHFUL_TIMING_PLAN.md +++ b/docs/internal/FAITHFUL_TIMING_PLAN.md @@ -213,6 +213,8 @@ on a fixed region -> next. ## 5. Status / Log (update every session) +- **2026-10-21 (BRIEF-4 GPU timing):** Split TIME_ELAPSED brackets around command starvation and presentation waits. Real-context 30ms producer-idle control reports 35.141ms with the old bracket / 5.620ms active GPU work; Windows and Mac GL fixtures and render-thread unit checks pass. Completion stalls remain; dynamic-resolution reallocations are the next target. No guest or completion-clock changes. + - **2026-10-21 (BRIEF-4 depth state):** Removed per-batch GL state round trips, including the mask-check exception absent in the old experiment. Real-context state restoration and image/readback controls pass on Windows and Mac. Fullscreen quiet route remains unaccepted (8 completion gaps, 53.2% p99 busy). Investigating GPU query spans that include host pacing and provoke expensive dynamic-resolution reallocations. - **2026-10-21 (BRIEF-4 Stage 1):** Reused #722 display-height cap and added opt-in `supersample_disable_at_lines`; unchanged defaults for other titles. Resolution, replay, config-parser and R4 default checks pass on Windows and macOS. R4 fullscreen 8K route cap restores 60 Hz but completion gaps remain (6 quiet / 7 loaded); no stage acceptance claimed. See R4 `analysis/STATUS.md`. diff --git a/runtime/include/render_thread.h b/runtime/include/render_thread.h index cf6a9978..b5e2dc1a 100644 --- a/runtime/include/render_thread.h +++ b/runtime/include/render_thread.h @@ -66,6 +66,9 @@ typedef struct RtConfig { RtCtxFn ctx; void *user; RtTickFn tick; /* optional (NULL) */ + /* Optional: before a command wait, on the render thread with its context + * current and no queue mutex held (e.g. end a GPU timing bracket). */ + void (*idle)(void *user); } RtConfig; /* Start: the context must be current on the calling thread; on success it is diff --git a/runtime/src/gpu_gl_renderer.c b/runtime/src/gpu_gl_renderer.c index 787990b3..35738590 100644 --- a/runtime/src/gpu_gl_renderer.c +++ b/runtime/src/gpu_gl_renderer.c @@ -433,6 +433,7 @@ static void fg_flush(void); static void fg_invalidate(void); static uint64_t fg_tick(void *user, uint64_t now); static void fg_note_guest_frame(void); +static void rthf_gpu_pause(void); extern int psx_ws_prim_is_tagged(void); /* gpu.c: is the current GP0 prim sprite-tagged? */ extern int psx_ws_prim_in_backdrop(void); /* gpu.c: is its source addr in the flower-field struct? */ extern int gpu_ws_nw_flat_backdrop_enabled(void); /* gpu.c: per-title flat backdrop opt-in */ @@ -9851,6 +9852,8 @@ static void pt_end(void) { /* The swap: direct, or queued to the present thread. */ static void gl_present_swap(void) { + /* Swap/slot waits are host pacing, not execution time on the GPU. */ + rthf_gpu_pause(); if (!s_pt_on) { gl_window_swap(); return; } (void)pt_target_fbo(); /* a frame that never bound 0 still has its slot */ void *ready = p_glFenceSync(PT_SYNC_GPU_COMMANDS_COMPLETE, 0); @@ -11373,12 +11376,13 @@ static void rth_present_payload(uint16_t op, const uint8_t *p) { #define RTHF_Q 8 /* Frame generation pauses a frame's measurement while it draws (the frame * then has up to RTHF_SEG queries, summed). */ -#define RTHF_SEG 4 +#define RTHF_SEG 64 static _Atomic int s_rthf_want = 0; /* host: measure (dynres active) */ static int s_rthf_qok = -1; /* render thread: queries usable */ static GLuint s_rthf_q[RTHF_Q][RTHF_SEG]; static int s_rthf_nseg[RTHF_Q]; static uint64_t s_rthf_slot_cpu[RTHF_Q]; +static int s_rthf_gpu_active = 0; static int s_rthf_paused = 0; /* a pause ended this frame's query */ static uint64_t s_rthf_pause_t0 = 0, s_rthf_pause_swap = 0, s_rthf_excl = 0; static void fg_note_real_cost(uint64_t cpu_ns, uint64_t gpu_ns, int has_gpu); /* frame generation */ @@ -11426,6 +11430,37 @@ static void rthf_poll(void) { } } +/* TIME_ELAPSED includes wall time when the command stream is starved. + * Close it before host waits and reopen only for a subsequent record. */ +static int rthf_active_segments(void) { + static int enabled = -1; + if (enabled < 0) { + const char *e = getenv("PSX_GL_GPU_ACTIVE_SEGMENTS"); + enabled = !(e && e[0] == '0'); + } + return enabled; +} +static void rthf_gpu_pause(void) { + if (!s_rthf_open || !s_rthf_has_q || !s_rthf_gpu_active || + !rthf_active_segments()) return; + p_glEndQuery(GL_TIME_ELAPSED); + s_rthf_gpu_active = 0; +} +static void rthf_gpu_resume(void) { + if (!s_rthf_open || !s_rthf_has_q || s_rthf_gpu_active || s_rthf_paused) return; + const unsigned i = s_rthf_head % RTHF_Q; + if (s_rthf_nseg[i] == RTHF_SEG) { s_rthf_taint = 1; return; } + p_glBeginQuery(GL_TIME_ELAPSED, s_rthf_q[i][s_rthf_nseg[i]++]); + s_rthf_gpu_active = 1; +} +static void gl_rth_idle(void *user) { + (void)user; + int active = s_rthf_gpu_active; + rthf_gpu_pause(); + /* Submit the end marker before sleeping; it must reach the GPU now. */ + if (active && !s_rthf_gpu_active) glFlush(); +} + static void rthf_begin(void) { if (s_rthf_qok < 0) { s_rthf_qok = (p_glGenQueries && p_glBeginQuery && p_glEndQuery && @@ -11434,6 +11469,7 @@ static void rthf_begin(void) { if (s_rthf_qok) p_glGenQueries(RTHF_Q * RTHF_SEG, &s_rthf_q[0][0]); } s_rthf_open = 1; + s_rthf_gpu_active = 0; s_rthf_taint = 0; s_rthf_paused = 0; s_rthf_excl = 0; @@ -11444,8 +11480,8 @@ static void rthf_begin(void) { if (s_rthf_has_q) { gl_perf_yield(); /* close frame_perf's open bracket, if any */ const unsigned i = s_rthf_head % RTHF_Q; - s_rthf_nseg[i] = 1; - p_glBeginQuery(GL_TIME_ELAPSED, s_rthf_q[i][0]); + s_rthf_nseg[i] = 0; + rthf_gpu_resume(); } } @@ -11457,23 +11493,16 @@ static void rthf_pause(void) { s_rthf_paused = 1; s_rthf_pause_t0 = host_now_ns_rthf(); s_rthf_pause_swap = s_rthf_swap_ns; - if (s_rthf_has_q) p_glEndQuery(GL_TIME_ELAPSED); + if (s_rthf_has_q && s_rthf_gpu_active) { + p_glEndQuery(GL_TIME_ELAPSED); s_rthf_gpu_active = 0; + } } static void rthf_resume(void) { if (!s_rthf_open || !s_rthf_paused) return; s_rthf_paused = 0; s_rthf_excl += host_now_ns_rthf() - s_rthf_pause_t0; s_rthf_swap_ns = s_rthf_pause_swap; /* the generated frames' swaps */ - if (s_rthf_has_q) { - const unsigned i = s_rthf_head % RTHF_Q; - if (s_rthf_nseg[i] < RTHF_SEG) { - p_glBeginQuery(GL_TIME_ELAPSED, s_rthf_q[i][s_rthf_nseg[i]++]); - } else { - /* Out of segments: the rest of the frame goes unmeasured. */ - s_rthf_taint = 1; - p_glBeginQuery(GL_TIME_ELAPSED, s_rthf_q[i][RTHF_SEG - 1]); - } - } + rthf_gpu_resume(); } static void rthf_end(void) { @@ -11484,7 +11513,8 @@ static void rthf_end(void) { /* The query pair is still issued so the ring stays in order; the * frame is not published. */ if (s_rthf_has_q) { - p_glEndQuery(GL_TIME_ELAPSED); + if (s_rthf_gpu_active) p_glEndQuery(GL_TIME_ELAPSED); + s_rthf_gpu_active = 0; s_rthf_tail = ++s_rthf_head; /* drop it and anything older */ } atomic_fetch_add(&s_rthf_dropped, 1); @@ -11498,7 +11528,8 @@ static void rthf_end(void) { const uint64_t cpu = span > skip ? span - skip : 0; if (s_rthf_has_q) { const unsigned i = s_rthf_head % RTHF_Q; - p_glEndQuery(GL_TIME_ELAPSED); + if (s_rthf_gpu_active) p_glEndQuery(GL_TIME_ELAPSED); + s_rthf_gpu_active = 0; s_rthf_slot_cpu[i] = cpu; s_rthf_head++; } else { @@ -13988,6 +14019,7 @@ static void gl_rth_exec(void *user, const RtCmd *c, const void *payload) { if (c->op == RTH_FRAME) { rthf_end(); return; } if (!s_rthf_open && (atomic_load_explicit(&s_rthf_want, memory_order_relaxed) || s_fg_on)) rthf_begin(); + rthf_gpu_resume(); if (s_fg_on) fg_capture(c, payload); switch (c->op) { case RTH_SEMI: glb_set_semi_transparency(v[0], v[1]); break; @@ -14134,6 +14166,7 @@ int gl_renderer_render_thread_start(int max_frames) { cfg.exec = gl_rth_exec; cfg.ctx = gl_rth_ctx; cfg.user = NULL; + cfg.idle = gl_rth_idle; cfg.tick = fg_tick; fg_invalidate(); (void)pt_begin(); /* [video] present_thread; falls back to direct swaps */ diff --git a/runtime/src/render_thread.c b/runtime/src/render_thread.c index 0cd14fde..397a25f6 100644 --- a/runtime/src/render_thread.c +++ b/runtime/src/render_thread.c @@ -99,6 +99,7 @@ static struct { RtCtxFn ctx; void *user; RtTickFn tick; + void (*idle)(void *user); uint64_t tick_at; /* consumer: next tick deadline (0 = none) */ /* shared positions / counters */ @@ -218,6 +219,7 @@ static void *render_main(void *arg) spun++; } if (atomic_load_explicit(&R.wpos, memory_order_acquire) != r) continue; + if (R.idle) R.idle(R.user); uint64_t t0 = now_ns(); mtx_lock(&R.mtx); atomic_store(&R.render_sleeping, 1); @@ -434,6 +436,7 @@ int rt_start(const RtConfig *cfg) { R.ctx = cfg->ctx; R.user = cfg->user; R.tick = cfg->tick; + R.idle = cfg->idle; R.tick_at = 0; mtx_init(&R.mtx); cnd_init(&R.cv_work); diff --git a/runtime/tests/run_gl_render_thread.py b/runtime/tests/run_gl_render_thread.py index cf088417..3c218777 100644 --- a/runtime/tests/run_gl_render_thread.py +++ b/runtime/tests/run_gl_render_thread.py @@ -170,6 +170,11 @@ def main(): print(f"FAIL scale {s} dynres: {k} differs with the render thread on " f"({runs[0][k]} off, {runs[1][k]} on)") ok = False + # A paced producer must not turn an inexpensive draw into 30ms GPU work. + r = run([probe, 4, 1, args.frames, "idle"]) + print("producer-idle timing:", r.returncode, r.stdout.strip().splitlines()[-8:], r.stderr[-800:]) + if r.returncode or parse(r.stdout)["failures"] != 0: + ok = False print("PASS" if ok else "FAIL") return 0 if ok else 1 diff --git a/runtime/tests/test_gl_render_thread.c b/runtime/tests/test_gl_render_thread.c index 39a4bd77..134a6ae3 100644 --- a/runtime/tests/test_gl_render_thread.c +++ b/runtime/tests/test_gl_render_thread.c @@ -115,6 +115,7 @@ static uint64_t fnv(const void *pp, size_t n, uint64_t h) { for (size_t i = 0; i < n; i++) { h ^= p[i]; h *= 0x100000001b3ull; } return h; } +static int timing_idle; static uint64_t rb_digest = 0xcbf29ce484222325ull; static uint32_t rng = 0x2468ace1u; static uint32_t rnd(void) { rng ^= rng << 13; rng ^= rng >> 17; rng ^= rng << 5; return rng; } @@ -235,6 +236,10 @@ static void frame(int f, int buf_x) { rb_digest = fnv(out, sizeof out, rb_digest); } gl_renderer_present_vram(buf_x, 0, FRAME_W, FRAME_H, 0, 0); + if (timing_idle && rt_running()) { + rt_drain(); + SDL_Delay(30); /* producer pacing after the rendered image is submitted */ + } gl_renderer_render_thread_frame_boundary(); } @@ -243,6 +248,7 @@ int main(int argc, char **argv) { int threaded = argc > 2 && argv[2][0] == '1'; int frames = argc > 3 ? atoi(argv[3]) : 80; int dynres = argc > 4 && !strcmp(argv[4], "dynres"); + timing_idle = argc > 4 && !strcmp(argv[4], "idle"); /* No video device, window or GL context (headless, Windows over SSH): * exit 77, which the harness reports as a CTest skip. */ if (SDL_Init(SDL_INIT_VIDEO) != 0) { @@ -310,6 +316,7 @@ int main(int argc, char **argv) { check(gl_renderer_dynamic_resolution_ceiling() == scale, "dynres ceiling"); if (threaded) gl_renderer_render_thread_measure(1); } + if (timing_idle && threaded) gl_renderer_render_thread_measure(1); static const int levels[] = { 2, 1, 3, 1, 4, 2 }; int nsteps = 0, level = scale; for (int f = 0; f < frames; f++) { @@ -345,6 +352,17 @@ int main(int argc, char **argv) { } } + if (timing_idle && threaded) { + gl_renderer_render_thread_sync("idle timing check"); + GlRthCosts co; + gl_renderer_render_thread_costs(&co); + double gpu_ms = co.gpu_frames ? (double)co.gpu_ns / co.gpu_frames * 1e-6 : 0.0; + printf("idle_gpu_ms=%.3f gpu_frames=%llu\n", gpu_ms, (unsigned long long)co.gpu_frames); + check(co.gpu_frames > 0, "idle timing has completed GPU samples"); + if (rthf_active_segments()) + check(gpu_ms < 15.0, "GPU work excludes the 30ms producer wait"); + } + /* Guest-visible VRAM, the frame at internal resolution, the wide surface. */ static uint16_t native[1024 * 512]; gr_vram_transfer_out(0, 0, 1024, 512, native);