D250: getenv() caching fix -- root cause of the Dam fps drop (plus sysSleep unit fix, GE_D250 probe, perf.ps1) (#75)

* D250: fix sysSleep unit-conversion bug in frame-pacing; add GE_D250 lvlRender probe

port/fast3d/gfx_sdl2.cpp sync_framerate_with_timer() computed the
remaining frame budget in 100ns units (qpc_to_100ns) and passed it
straight into sysSleep(), which takes microseconds -- a real 10x
oversleep whenever that branch fires. Genuine bug, but only active
when target_fps is nonzero (tied to Input/Video FpsCap); confirmed via
live testing that it is NOT the active cause of the user's reported
~45-50fps with FpsCap=0/VSync=0, where this pacing path never runs.

Added GE_D250 (src/boss.c, #ifdef PORT) to isolate lvlRender()'s
DL-building cost (culling/animation/scene traversal) from gfx_run's
already-measured software-RSP interpretation cost. Live test on Dam
shows lvlRender averaging ~0.5-1.5ms -- also not the bottleneck.

Documented in docs/dev/GE-ENV-PROBES.md (GE_D250 row). findings.md
D250 update to follow after rebase.

Claude-Session: https://claude.ai/code/session_016DQUKGLZxFtPy52MkKXXog

* docs(D250): live A/B session -- MSAA/aniso/FOV/resolution/vsync all ruled out

Live session with the user driving the game directly, confirmed the
sim-healthy/render-sagging pattern from earlier idle testing reproduces
under real play on Dam. One-at-a-time A/B via the F10 overlay ruled out
MSAA, anisotropy, FOV, resolution (1280x960 fullscreen vs 640x480
windowed), and VSync (render never exceeds ~60 even uncapped) as the
cause -- the cost is resolution/GPU-setting-independent.

gfx_run (~6-10ms) + lvlRender (~0.5-1.5ms, via the new GE_D250 probe)
together don't account for the real ~20-22ms/frame. Leading remaining
suspect: the emulated N64 thread-handoff/scheduler round-trip
(gesched.c/sched.c) -- real OS context-switch/wake latency standing in
for what was free hardware handoff on N64. Needs a real profiler
(Visual Studio / WPR) attached during a live bad-fps moment to confirm;
ad-hoc per-call timers have now ruled out the two most obvious CPU call
sites without finding the cost.

Claude-Session: https://claude.ai/code/session_016DQUKGLZxFtPy52MkKXXog

* D250: fix uncached getenv() in fast3d hot paths -- root cause of the fps drop

A live WPR/xperf CPU trace (tools_pc/perf.ps1, new sister script to
debug.ps1) with Microsoft public symbols resolved found the dominant
render thread spending only 5.2% of its CPU time in the game's own
code -- 43% was in msvcrt.dll, and getenv()/_getenv_helper_nolock
alone accounted for ~50% of the thread's total CPU time.

Root cause: port/fast3d/gfx_pc.cpp's import_texture() (runs on every
texture bind) and several per-triangle/per-G_SETCOMBINE debug-probe
checks (GE_DTEX, GE_TEXDUMP, GE_TEXRAW, GE_D229 x2, GE_D172 x2, plus
GE_TEXDUMP/GE_PCDUMP in gfx_opengl.cpp) called getenv() uncached on
every call, unlike the safe static-cached pattern already used
elsewhere in this codebase. On a texture-heavy scene that's tens of
thousands of locked, locale-aware Windows CRT environment lookups per
second -- invisible to both of the timers added earlier this session
(gfx_run's own cost measurement and the new GE_D250 lvlRender probe),
since neither isolates CRT/library time from the game's own code.

Fix: cache every getenv() site in gfx_pc.cpp/gfx_opengl.cpp with the
established static-int pattern. Narrow, mechanical, no logic change.

Verified: the exact idle-Dam test that was pinned at 45-50fps before
the fix now holds a rock-steady 60-61fps, zero dips. Also explains why
the earlier MSAA/aniso/FOV/resolution/vsync A/B pass all showed "no
change" -- the getenv() cost was a large per-call constant that
swamped any real, smaller resolution-dependent GPU cost at every
setting tried.

Residual, separate issue found once this was fixed: still runs badly
at 1440p+ (640x480 now holds a clean 60fps) -- likely the real GPU
fill-rate cost the getenv() bug was masking, now exposed on its own.
Not yet investigated.

docs/dev/findings.md D250 updated with the full root-cause writeup.
docs/porting-notes.md gets a new lesson under section E (cache
getenv() in any hot-path probe). tools_pc/perf.ps1 automates the
trace-and-analyze workflow for next time.

Claude-Session: https://claude.ai/code/session_016DQUKGLZxFtPy52MkKXXog

* docs(D250): correct the 1440p+ follow-up -- it was a stale-build false alarm

User re-tested 1440p/4K on the actual getenv-fix build and confirmed
it holds up fine too. The "still runs badly at 1440p+" report was
from before the fix was live, same stale-build class as the DLL-load
false alarm earlier in the session. D250 is fully resolved across all
resolutions tested, not just 640x480.

Claude-Session: https://claude.ai/code/session_016DQUKGLZxFtPy52MkKXXog

* docs: add missing GE_D219RAW row to GE-ENV-PROBES.md (CI validate fix)

Pre-existing gap unrelated to this branch's own changes -- gen_env_probes.py
--check caught it now since it runs on every PR. GE_D219RAW has had live
getenv() sites in src/game/image.c since the D219 investigation but was
never added to the probe doc.
This commit is contained in:
James Dansereau authored and GitHub committed 2026-09-13 09:33:36 -04:00
1 parent ef0c0900b4
commit 70bc9d65b5
9 files changed
+239 -16

No files matched your search

+35
View File
@@ -2,6 +2,7 @@
#include <PR/os.h>
#ifdef PORT
#include <stdlib.h>
#include <stdio.h>
#endif
#include "bondview.h"
#include <bondconstants.h>
@@ -581,7 +582,41 @@ void bossMainloop(void)
}
}
#ifdef PORT
/* D250: isolate DL-building cost (culling,
* animation, scene traversal) from gfx_run's
* software-RSP interpretation cost, measured
* separately by libultra.c's "frame rendered in
* us" (D193 already showed that one stays well
* under budget while real fps still sags -- this
* finds out whether lvlRender is where the rest
* of the missing time goes). Env-gated, no-op
* unless GE_D250 is set. */
{
static int gd250 = -1;
static OSTime d250Sum = 0, d250WallStart = 0;
static int d250N = 0;
OSTime d250T0 = 0;
if (gd250 < 0) gd250 = getenv("GE_D250") != NULL;
if (gd250) d250T0 = osGetTime();
#endif
gdl = lvlRender(gdl);
#ifdef PORT
if (gd250) {
OSTime now = osGetTime();
d250Sum += now - d250T0;
d250N++;
if (!d250WallStart) d250WallStart = now;
if (now - d250WallStart >= 1000000) {
fprintf(stderr,
"[D250] lvlRender avg=%lluus n=%d\n",
(unsigned long long)(d250Sum / (d250N ? d250N : 1)),
d250N);
d250Sum = 0; d250N = 0; d250WallStart = now;
}
}
}
#endif
// Lets Visualise the Coverage Value used for Scilohete Anti-Ailising (edges)
// (done on the VI), also produces a cool looking linemode - providing AA is working.