From 36de85e78933b27af68a7a2146de1d23ee671e7e Mon Sep 17 00:00:00 2001 From: James Dansereau <106631954+jkdansereau@users.noreply.github.com> Date: Thu, 24 Sep 2026 11:11:47 -0400 Subject: [PATCH] D339 (#92): GE_PERFSTAT perf probe + measured CPU budget (CPU likely not the low-end bottleneck; GPU suspect) Env-gated per-frame timing: render phases, tris/batches, game-thread busy, GL_TIME_ELAPSED GPU timer. Measured ~2.1 ms/frame total CPU on the heaviest levels here; the GPU timer is only meaningful when GPU-bound. Target-hardware numbers needed before a low-end preset. Golden 3/3; Win + Linux builds. --- docs/dev/GE-ENV-PROBES.md | 1 + docs/dev/findings-index.csv | 1 + docs/dev/findings.md | 20 +++++++++++++++ port/fast3d/gfx_opengl.cpp | 42 +++++++++++++++++++++++++++++++ port/fast3d/gfx_pc.cpp | 50 +++++++++++++++++++++++++++++++++++++ src/boss.c | 20 +++++++++++++++ 6 files changed, 134 insertions(+) diff --git a/docs/dev/GE-ENV-PROBES.md b/docs/dev/GE-ENV-PROBES.md index f2621f41..792ae4f7 100644 --- a/docs/dev/GE-ENV-PROBES.md +++ b/docs/dev/GE-ENV-PROBES.md @@ -72,6 +72,7 @@ Two classes: | `GE_D235_RELOAD=` | `src/boss.c` (same block + `bossMainloop` retrace branch) | **TEMP** reload harness: once the title stage loads after the first level (e.g. after a scripted watch Abort), wait `` retraces, then re-enter that level via `bossSetLoadedStage()`, the front end's own mission-start call. A headless death/restart without the pointer-menu walk. Pair with `GE_INPUTSCRIPT="800:START;1200:A;1300:RIGHT;1400:A"` (abort) on `-level_XX`. | **TEMP** (D235; remove when D235 closes) | | `GE_D235_NEXT=` | `src/boss.c` (with `GE_D235_RELOAD`) | **TEMP**: re-enter a *different* stage after the abort (level A → title → level B), used for D336 (Runway → Frigate). `GE_D85TEX=1` now also logs each stage's texture-pool size and address range (`src/game/initmttex.c`). | **TEMP** | | `GE_AIMLOG=1` (+ `GE_INPUTSCRIPT` tokens `MDX` `MDY` `RHOLD` `LHOLD` `RREL`) | `port/src/input.c` | D337 aim-model harness: scripted sustained mouse deltas (treated as a grabbed mouse) and aim holds, plus a per-poll line with aim state, active device, the game's drawn crosshair x, `crosshair_x/y_pos` and camera angles. Measures range, edge-scroll and jitter headlessly. | **live** | +| `GE_PERFSTAT=1` | `port/fast3d/gfx_pc.cpp` (`gfx_run`/`gfx_end_frame`), `port/fast3d/gfx_opengl.cpp` (start/end_frame), `src/boss.c` (main loop) | #92/D339 perf probe: per-300-frame averages of render phases (pre / display-list / post / swap+pace), tris and draw batches per frame, game-thread busy time per scheduler message, and a GL_TIME_ELAPSED GPU timer (meaningful only when GPU-bound). | **live** | | `GE_D75V` | `port/fast3d/gfx_pc.cpp` (`gfx_sp_vertex`, end of the copy/transform loop; cached env check) | D75 (Nintendo logo) per-batch vertex probe: for each `G_VTX` batch in frames `lo..hi`, logs frame#, source pointer, n_vertices, original dest_index, raw ob[0..2] of the first vertex, min/max of the transformed x/y/z/w across the batch, and the MP translation row. Used to prove the transform is correct (M-195) and that every batch encodes v0=0 (slot-overwrite hypothesis). Value form `"lo-hi"` (e.g. `300-900` = the logo screen); unset = off. | **live** (D75) | | `GE_D75D` | `port/fast3d/gfx_pc.cpp` (`gfx_sp_vertex` G_VTX case + `gfx_sp_tri1` rejection/emit gates; cached env check) | D75 (Nintendo logo) per-frame draw-path probe (M-196): for frames `lo..hi`, logs one line/frame with the V/T token stream (`seq`), max triangle vertex index, cumulative vertices loaded, and per-triangle accounting — trivial-reject / backface-cull counts, how many tris reach GL, how many of those are on-screen (NDC bbox ⊂ [−1,1]²), invisible-flag count, vertex-color min/max, first oml word, depth z/w range + NaN count, texture-sampler presence (`utex` = GL shader, `cutex` = combiner), combine mode, prim/env color. Used to REFUTE the slot-overwrite hypothesis (DL is streamed, max index 15) and narrow the bug to a texture-modulate material rendering black. M-197 added logo-mode `lg_*` fields (sampled only on tris with the logo combine word — the frame-level `utex`/`cutex` are first-tri-wins and were the source of the "combiner claims 0" false anomaly): `lg_utex`/`lg_tex` + tile-0 descriptor + texture buffer address/id/size for the logo material. Value form `"lo-hi"` (logo window ≈ `244-320` on a bare front-end boot); unset = off. Companion one-shot `D75DCC:` log in `gfx_generate_cc` fires when `combine_mode==0x009ffe4f19ffe4f1` to decode the logo's combine slots. | **live** (D75) | diff --git a/docs/dev/findings-index.csv b/docs/dev/findings-index.csv index 174db9e4..fd6f2ae3 100644 --- a/docs/dev/findings-index.csv +++ b/docs/dev/findings-index.csv @@ -216,3 +216,4 @@ D335,?,"Native widescreen, HUD + front end (WIDESCREEN-FOV-PLAN Phase 3):","IMPL D336,FIXED,"Frigate (and any level) ""all polygons break except the gun"" after turning:","FIXED (src/game/bondhead.c #ifdef PORT, ABI/layout); headless repro (Runway → exit → Frigate → turn, D294 2× room pool) clean, D156 0 fires; golden 3/3; Win + Linux builds." D337,OPEN,Aim modes folded (user decision):,IMPLEMENTED (port/src/input.c + optionsoverlay.c); headless-measured with new scripted-mouse harness; golden 3/3; Win + Linux builds. D338,?,"Input.AimRange (F10 ""Aim range""):","IMPLEMENTED + measured (PC 98%/72%, N64 65%/49%); golden 3/3; Win + Linux builds." +D339,PARTIAL,"#92 (low-end ~30 fps, Celeron N3060 / HD 400) —",INVESTIGATING — probe landed; target-hardware numbers needed before any fix. diff --git a/docs/dev/findings.md b/docs/dev/findings.md index 1c7a836c..30580a34 100644 --- a/docs/dev/findings.md +++ b/docs/dev/findings.md @@ -624,6 +624,7 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121). | D336 | **Frigate (and any level) "all polygons break except the gun" after turning: Bond's head-bob anim read two never-written placeholder fields (`field_5C0`, `animFlipFlag`) that on N64 are raw-offset aliases into the inline `player.model` (D100 follow-up; A1 class). Likely the D311 upstream anim-poison source.** — full `## D336` entry at file tail | FIXED (src/game/bondhead.c `#ifdef PORT`, ABI/layout); headless repro (Runway → exit → Frigate → turn, D294 2× room pool) clean, D156 0 fires; golden 3/3; Win + Linux builds. **User-confirmed 2026-09-24.** | | D337 | **Aim modes folded (user decision): N64 (default) = the N64 aim model with the mouse fed through the game's integrator at PD's damp (D332 made default); CENTRED (PC) opt-in; Q/L and Toggle-aim now route mouse aim like RMB; pad/keyboard aim no longer swallowed by the mouse integration.** — full `## D337` entry at file tail | IMPLEMENTED (port/src/input.c + optionsoverlay.c); headless-measured with new scripted-mouse harness; golden 3/3; Win + Linux builds. Open: N64-range calibration decision. | | D338 | **`Input.AimRange` (F10 "Aim range"): PC (default, GEPD/mouse-injector full-screen crosshair) or N64 (original stick limits: 65% of half-width, camera turn from ~49%).** — full `## D338` entry at file tail | IMPLEMENTED + measured (PC 98%/72%, N64 65%/49%); golden 3/3; Win + Linux builds. | +| D339 | **#92 (low-end ~30 fps, Celeron N3060 / HD 400) — measured CPU budget: game thread ~0.2–0.35 ms/frame, render-thread display-list pass 0.4–1.8 ms/frame on this box; CPU very likely not the bottleneck. New `GE_PERFSTAT=1` probe (render phases, tris/batches, game-thread busy, GPU timer query).** — full `## D339` entry at file tail | INVESTIGATING — probe landed; target-hardware numbers needed before any fix. | Phase 2 replaced the Phase-1 demo loop with the real `mainproc()` on real OS threads, compiled GE's real `src/sched.c`, and brought in PD's fast3d software @@ -13304,3 +13305,22 @@ Implemented as `Input.PdMouseAim` (**default off**, because it changes aim feel) **User decision (D337 follow-up):** keep the GEPD / mouse-injector feel (the crosshair reaches the screen edge, edge-scroll from 72%) as the PC default even though it isn't N64-exact, and offer the original behaviour as an option. **`Input.AimRange`** 0 = PC, 1 = N64 (F10 "Aim range", hidden while the aim style is Centred (PC)). N64 derivation: aim turn is `stick × 0.65/80` per tick, so full deflection settles at a drawn offset of 0.65 × half-width regardless of weapon damp (`screen = pos × (1−damp) × W/2`, gunfire.c), and the camera turns past stick 60/80 = 75% of that range. Implementation: the mouse accumulator is unchanged; its screen mapping is scaled by 0.65 (PD turn and legacy GEPD write alike) and the edge-scroll threshold moves to 0.75. The non-aim "adopt" of the game crosshair into the accumulator now converts through the game's screen mapping and the range scale, so aim entry never jumps (it copied raw units before, a small pre-existing mismatch on the PD path). **Measured (GE_AIMLOG harness, 3 px/poll sweep):** PC max drawn x 316/320 (98%, the game's 4 px edge clamp), camera turn from 72%; N64 max 264 (65%), camera turn from 237.9 px (49%); aim entry at 160 (centre) in both. Golden 3/3; Windows + Linux builds clean. **D337/D338 user feel check (2026-09-24):** "Seems good." The session exercised the legacy-key migration live: the user's ini had `AimStyle = 2` (Centred) from D333 testing and loaded as `AimMode = 1` as designed. User's ini then set back to `AimMode = 0` (N64, their stated preference), `AimRange = 0` (PC). +## D339 — #92 low-end performance: CPU budget measured, GPU the likely bottleneck; GE_PERFSTAT probe (2026-09-24) + +**Report (#92, filed by the maintainer for a user):** Celeron N3060 (2C, 1.6 GHz) + Intel HD 400 (Bay Trail), Windows 10: the port runs ~30 fps, "a bit higher in enclosed areas", while the PD PC port holds 60 on the same machine. + +**Probe (`GE_PERFSTAT=1`, env-gated, zero cost when unset):** `port/fast3d/gfx_pc.cpp` averages over 300 frames: `pre` (frame setup), `dl` (display-list pass = software RSP + GL draw submission), `post` (MSAA resolve / end_frame), `swap/pace` (swap_buffers_begin, which contains the D186 frame-pacing wait), triangles and draw batches per frame. `src/boss.c` reports game-thread busy time per scheduler message (~2 messages/frame). `port/fast3d/gfx_opengl.cpp` adds a double-buffered `GL_TIME_ELAPSED` GPU timer (logged with `GL_RENDERER`/`GL_VERSION`). + +**Measured (this machine: RTX 5090, fast desktop CPU; 1280×720, defaults):** + +| Level | dl (ms) | tris/frame | batches/frame | game thread (ms/frame) | +|---|---|---|---|---| +| Bunker 1 | 0.32–0.39 | ~560 | ~99 | ~0.2 | +| Dam | 1.24 | ~2,700 | ~233 | — | +| Streets | 1.69–1.71 | ~3,080 | ~411 | ~0.35 | +| Egypt | 1.77–1.79 | ~3,560 | ~322 | ~0.3 | + +`pre`/`post` ≈ 0; `swap/pace` ≈ 2 ms is the pacing wait, not work. **CPU cost scales with scene complexity** (matching the reporter's "higher in enclosed areas"), but totals only ~2.1 ms/frame at the heaviest. Scaled for an N3060 (~5× slower per core, logic and render on separate threads), that's roughly 2 + 9 ms on two cores, which fits in 16.7 ms. CPU is therefore unlikely to be what pins the reporter at 30. **GPU is the prime suspect:** an HD 400 at native resolution with the port's defaults (MSAA 4×, 16× anisotropic, the 3-point filter shader) against the PD port's lighter defaults. **GPU timer caveat:** on this RTX 5090 the query read 1.7 ms at defaults and 4.1 ms at MSAA 1 / aniso 1 / bilinear, an inversion that shows the timer also captures swap-chain back-buffer waits on the direct (non-FBO) path. It is only meaningful on a GPU-bound machine (it would then read close to the frame time). + +**Next (needs HD 400-class hardware, not reporter logs):** run `GE_PERFSTAT=1` on a comparable machine at defaults vs MSAA 1 / aniso 1 / bilinear; if GPU-bound, consider a first-run low-end preset (the Steam Deck preset, `da31edaa`, is the precedent) keyed on the GL renderer. CPU-side headroom if ever needed: batches per frame (100–411) is the obvious lever (state-change batching in `gfx_flush`). + diff --git a/port/fast3d/gfx_opengl.cpp b/port/fast3d/gfx_opengl.cpp index 4177a203..eb8423d7 100644 --- a/port/fast3d/gfx_opengl.cpp +++ b/port/fast3d/gfx_opengl.cpp @@ -1095,12 +1095,54 @@ static void gfx_opengl_init(void) { static void gfx_opengl_on_resize(void) { } +/* #92 perf probe (GE_PERFSTAT=1): GPU time per frame via GL_TIME_ELAPSED, + * double-buffered so reading never stalls the pipeline. Skipped when the + * driver lacks timer queries. Tells a low-end reporter's log whether frames + * are GPU-bound (render/MSAA/filtering cost) or CPU-bound. */ +static int s_gpuq_on = -1; +static GLuint s_gpuq[2]; +static int s_gpuq_idx = 0, s_gpuq_valid[2] = { 0, 0 }; +static double s_gpuq_ms = 0.0; +static int s_gpuq_n = 0, s_gpuq_frames = 0; + static void gfx_opengl_start_frame(void) { frame_count++; + if (s_gpuq_on < 0) { + s_gpuq_on = getenv("GE_PERFSTAT") != NULL && glGenQueries != NULL && + glGetQueryObjectui64v != NULL && glBeginQuery != NULL; + if (s_gpuq_on) { + glGenQueries(2, s_gpuq); + fprintf(stderr, "PERFSTAT gpu timer on: %s | %s\n", + (const char *)glGetString(GL_RENDERER), (const char *)glGetString(GL_VERSION)); + } + } + if (s_gpuq_on == 1) { + if (s_gpuq_valid[s_gpuq_idx]) { + GLuint avail = 0; + glGetQueryObjectuiv(s_gpuq[s_gpuq_idx], GL_QUERY_RESULT_AVAILABLE, &avail); + if (avail) { + GLuint64 ns = 0; + glGetQueryObjectui64v(s_gpuq[s_gpuq_idx], GL_QUERY_RESULT, &ns); + s_gpuq_ms += (double)ns / 1.0e6; + s_gpuq_n++; + } + } + glBeginQuery(GL_TIME_ELAPSED, s_gpuq[s_gpuq_idx]); + } } static void gfx_opengl_end_frame(void) { glFlush(); + if (s_gpuq_on == 1) { + glEndQuery(GL_TIME_ELAPSED); + s_gpuq_valid[s_gpuq_idx] = 1; + s_gpuq_idx ^= 1; + if (++s_gpuq_frames % 300 == 0 && s_gpuq_n > 0) { + fprintf(stderr, "PERFSTAT gpu=%.2fms/frame (avg over %d frames)\n", s_gpuq_ms / s_gpuq_n, s_gpuq_n); + s_gpuq_ms = 0.0; + s_gpuq_n = 0; + } + } } /* Frame capture (dev tool, env GE_PCDUMP) — see gfx_opengl.h. TEMP D70: read diff --git a/port/fast3d/gfx_pc.cpp b/port/fast3d/gfx_pc.cpp index bf0cbeeb..dd002809 100644 --- a/port/fast3d/gfx_pc.cpp +++ b/port/fast3d/gfx_pc.cpp @@ -16,6 +16,7 @@ #include #include #include +#include #include #ifndef _LANGUAGE_C @@ -288,8 +289,13 @@ static constexpr float clampf(const float x, const float min, const float max) { return (x < min) ? min : (x > max) ? max : x; } +/* #92 perf probe (GE_PERFSTAT=1): per-frame counters, see gfx_run. */ +static uint64_t s_perf_batches = 0, s_perf_tris = 0; + static void gfx_flush(void) { if (buf_vbo_len > 0) { + s_perf_batches++; + s_perf_tris += buf_vbo_num_tris; gfx_rapi->draw_triangles(buf_vbo, buf_vbo_len, buf_vbo_num_tris); buf_vbo_len = 0; buf_vbo_num_tris = 0; @@ -4071,7 +4077,21 @@ uint32_t num_dls = 0; * frame is byte-identical to before (golden dumps unaffected). */ extern "C" Gfx* optionsOverlayEmit(void); +static uint64_t gfx_perf_now_ns(void) { + return (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); +} +static int gfx_perfstat_on(void) { + static int on = -1; + if (on < 0) on = getenv("GE_PERFSTAT") != NULL; + return on; +} +static double s_perf_dl = 0, s_perf_run = 0, s_perf_present = 0, s_perf_interval = 0; +static double s_perf_pre = 0, s_perf_post = 0, s_perf_swap = 0; +static uint64_t s_perf_frames = 0, s_perf_last_start = 0; + extern "C" void gfx_run(Gfx* commands) { + const uint64_t perf_t0 = gfx_perfstat_on() ? gfx_perf_now_ns() : 0; ++num_dls; gfx_sp_reset(); @@ -4093,6 +4113,7 @@ extern "C" void gfx_run(Gfx* commands) { rdp.viewport_or_scissor_changed = true; rendering_state.viewport = {}; rendering_state.scissor = {}; + const uint64_t perf_tpre = perf_t0 ? gfx_perf_now_ns() : 0; gfx_run_dl(commands); { Gfx* overlay = optionsOverlayEmit(); @@ -4101,6 +4122,7 @@ extern "C" void gfx_run(Gfx* commands) { } } gfx_flush(); + const uint64_t perf_t1 = perf_t0 ? gfx_perf_now_ns() : 0; gfxFramebuffer = 0; if (game_renders_to_framebuffer) { @@ -4123,14 +4145,42 @@ extern "C" void gfx_run(Gfx* commands) { } gfx_rapi->end_frame(); + const uint64_t perf_tpost = perf_t0 ? gfx_perf_now_ns() : 0; gfx_wapi->swap_buffers_begin(); + if (perf_t0) { + s_perf_pre += (double)(perf_tpre - perf_t0) / 1.0e6; + s_perf_post += (double)(perf_tpost - perf_t1) / 1.0e6; + s_perf_swap += (double)(gfx_perf_now_ns() - perf_tpost) / 1.0e6; + const double f = 1.0e6; + const uint64_t t2 = gfx_perf_now_ns(); + s_perf_dl += (double)(perf_t1 - perf_tpre) / f; + s_perf_run += (double)(t2 - perf_t0) / f; + if (s_perf_last_start) s_perf_interval += (double)(perf_t0 - s_perf_last_start) / f; + s_perf_last_start = perf_t0; + } } extern "C" void gfx_end_frame(void) { + const uint64_t perf_t0 = gfx_perfstat_on() ? gfx_perf_now_ns() : 0; if (!dropped_frame) { gfx_rapi->finish_render(); gfx_wapi->swap_buffers_end(); } + if (perf_t0) { + const double f = 1.0e6; + s_perf_present += (double)(gfx_perf_now_ns() - perf_t0) / f; + if (++s_perf_frames % 300 == 0) { + const double n = 300.0; + fprintf(stderr, "PERFSTAT pre=%.2f post=%.2f swap/pace=%.2f | ", s_perf_pre / n, s_perf_post / n, s_perf_swap / n); + s_perf_pre = s_perf_post = s_perf_swap = 0; + fprintf(stderr, "frames=%llu dl=%.2fms run=%.2fms present=%.2fms interval=%.2fms (%.1f fps) tris=%.0f batches=%.0f\n", + (unsigned long long)s_perf_frames, s_perf_dl / n, s_perf_run / n, s_perf_present / n, + s_perf_interval / n, s_perf_interval > 0 ? 1000.0 * n / s_perf_interval : 0.0, + (double)s_perf_tris / n, (double)s_perf_batches / n); + s_perf_dl = s_perf_run = s_perf_present = s_perf_interval = 0; + s_perf_tris = s_perf_batches = 0; + } + } } extern "C" void gfx_set_target_fps(int fps) { diff --git a/src/boss.c b/src/boss.c index d026e294..0f019a32 100644 --- a/src/boss.c +++ b/src/boss.c @@ -588,7 +588,27 @@ void bossMainloop(void) while (g_MainStageNum < 0 || pendingGfx != 0) { +#ifdef PORT + /* #92 perf probe (GE_PERFSTAT=1): game-thread busy time between + * waking for a message and blocking again (logic + DL build). */ + { + static int pon = -1; static u32 tw = 0; static f64 busy = 0; static s32 n = 0; + if (pon < 0) pon = getenv("GE_PERFSTAT") != NULL; + if (pon) { + u32 now = osGetCount(); + if (tw) { busy += (f64)(u32)(now - tw); n++; } + if (n == 600) { + fprintf(stderr, "PERFSTAT game-thread busy=%.2fms/msg (avg over 600 msgs)\n", + busy / (f64)n / (f64)(OS_CPU_COUNTER / 1000)); + busy = 0; n = 0; + } + } + osRecvMesg(&gfxFrameMsgQ, (OSMesg *)&localGfxFrameMsg, OS_MESG_BLOCK); + if (pon) tw = osGetCount(); + } +#else osRecvMesg(&gfxFrameMsgQ, (OSMesg *)&localGfxFrameMsg, OS_MESG_BLOCK); +#endif switch (localGfxFrameMsg->gen.type) {