From 70bc9d65b5e43249bb96c64b3de3cec9e3bf9ba4 Mon Sep 17 00:00:00 2001 From: James Dansereau <106631954+jkdansereau@users.noreply.github.com> Date: Sun, 13 Sep 2026 09:33:36 -0400 Subject: [PATCH] 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. --- .gitignore | 2 + docs/dev/GE-ENV-PROBES.md | 2 + docs/dev/findings.md | 2 +- docs/porting-notes.md | 19 ++++++ port/fast3d/gfx_opengl.cpp | 13 +++- port/fast3d/gfx_pc.cpp | 44 +++++++++---- port/fast3d/gfx_sdl2.cpp | 8 ++- src/boss.c | 35 ++++++++++ tools_pc/perf.ps1 | 130 +++++++++++++++++++++++++++++++++++++ 9 files changed, 239 insertions(+), 16 deletions(-) create mode 100644 tools_pc/perf.ps1 diff --git a/.gitignore b/.gitignore index 998ea0ef..3445fb2b 100644 --- a/.gitignore +++ b/.gitignore @@ -142,6 +142,8 @@ ge007.crash.log run_out.log ppm/ screenshots/ +# tools_pc/perf.ps1 output (raw ETW traces + CSV analysis, regenerable) +perf_captures/ # local Mupen64 Plus checkout (N64 reference footage); binaries, do not commit tools_pc/mupen64/ # local N64 emulator checkout (D205 A/B reference) diff --git a/docs/dev/GE-ENV-PROBES.md b/docs/dev/GE-ENV-PROBES.md index 0ddd9134..fe9b1f5b 100644 --- a/docs/dev/GE-ENV-PROBES.md +++ b/docs/dev/GE-ENV-PROBES.md @@ -39,12 +39,14 @@ Two classes: | `GE_MIXERTRACE` | `port/src/mixer.c`, `src/audi.c` (`amDmaCallback`), `src/libultra/audio/load.c` (`_decodeChunk`, `alLoadParam`) | Per-opcode mixer trace to `mixertrace.log` (DMEM addresses, ADPCM books, decoded frames, `[DMAREQ]`/`[DMAHIT]`/`[DMAMISS]`/`[BINDTABLE]`). **WARNING: unbuffered per-opcode `fprintf`, ~25 MB/min. It slows the process enough to starve the audio thread — M-63 measured "audio at 13 % of real time" that was entirely this probe's own artifact. NEVER use it for timing-sensitive measurement; use `GE_D204`.** Grep it, never read it whole. | **live** (D202) — timing-unsafe | | `GE_TEXPITCH` | `port/fast3d/gfx_pc.cpp:924` (`gfx_tex_pitch_fix`, cached) | `=0` disables the D183 defensive de-stride in `import_texture` (default on). RC2/RC3 texture-shear A/B knob. | **live** (RC3 not finished) | | `GE_TEXRAW` | `port/fast3d/gfx_pc.cpp:1079` | With `GE_TEXDUMP`, also dumps the raw pre-import source bytes (`texdump/rNNN_f…_s…_WxH.bin`) so a decode bug can be told from a source-data bug offline (D183). | **live** (RC3 not finished) | +| `GE_D219RAW` | `src/game/image.c` (`texReadUncompressed`/`texChannelsToPixels`, `#ifdef PORT`) | Diagnostic-only, print-only (no behavior change): logs the runtime texture decompressor's bitstream header (texnum/format/width/height/compmethod) for every non-zlib wide-pixel image, plus a dump of the first row of decoded texels exactly as stored in the pool (post-`PORT_PIXEL16`, i.e. byte-swapped for the 16-bit family) for RGBA16/RGB15/IA16. No texnum filter — lets any suspect texture be cross-referenced against the offline ROM census (`scratch/d219_census.txt`) without narrowing by hand. | **live** (D219, closed — kept for future runtime-decoder triage) | | `GE_WRAPFIX` | `port/fast3d/gfx_pc.cpp:3166` (`gfx_set_wrap_fix`) | RC3 test override for the `Video.WrapFix` D74/D167 wrap-block path (`atoi != 0` wins over the ini). | **live** (RC3 not finished) | | `GE_SAVELOG` | `src/game/file.c:46`, `src/game/file2.c:16` (`SAVELOG` macro), `src/boss.c:749`, `src/game/objective_status.c:297,343` | Traces the campaign save/unlock chain (objective completion → `end_of_mission_briefing` → `fileWriteSave` → EEPROM). Used to confirm D157. `g_savelogObjOnce` gates the per-criterion dump to the `bossReturnTitleStage` call. | **live** (strip once a few more level boundaries are playtested) | | `GE_D160` | `src/boss.c:744`, `src/game/bondview2.c:791`, `src/aicommands.def:10055,10181,10236,10242,10247` (all `#ifdef PORT`) | Dam exit-cutscene (D148/D160) diagnostic: trace points in `bossReturnTitleStage`, `bondviewSetCameraMode`, and AI cmds `EndLevel`/`exit_level`/`CameraLookAtBondFromPad`/`CameraSwitch`. **Investigation in progress** — user owes a `GE_D160=1` Dam run. | **live** | | `GE_D193` | `src/game/frametiming.c` (`waitForNextFrame`, `#ifdef PORT`) | Per-wall-second line: `render=` rendered frames, `sim=` sim ticks delivered (Σ of the `deltaFrames`/`g_ClockTimer` fed downstream), `clamped=` frames whose catch-up hit `FRAMETIMING_PORT_MAX_CATCHUP`, `maxraw=` largest pre-clamp delta. Healthy steady state = `render=30 sim=60 clamped=0 maxraw=2` (measured M-80, all levels idle). Use to check whether the wall-clock timer under-advances under real AI load (D193). Cheap; safe for a full playtest. | **live** (D193) | | `GE_D193A` | `src/game/chr.c` (`chrTick` → `d193aSample`, plus `d193aMoved` in `chrUpdateAnim`; `#ifdef PORT`) | Per-wall-second per-ticked-chr locomotion telemetry (D193/D209): `chr=` chrnum, `act=` ACT_TYPE, `speed=` world-units travelled/s, `gtd=` g_GlobalTimerDelta, `tier=` `act_gopos.unk59` SPEED tier (0 walk / 1 run / 2 sprint; `-1` when not ACT_GOPOS), `gspd=` `act_gopos.speed` (**a turn rate, not a travel rate** — 0 means running straight), `typ=` PROP_TYPE (3=CHR, 6=VIEWER), `tick=`/`move=`/`frz=` chrTick entries vs `chrUpdateAnim` calls vs freeze-gated (move « tick = the chr is being visibility-culled out of its own locomotion; `move=0` at high `speed` = WAYMODE_MAGIC), `hid=` CHRFLAG_HIDDEN, then the root-motion scalars `scale` / `xlscale` / `animrate` / `playspeed` / `mspeed` (model->speed) / `endframe` / `anim` ptr / `aidx=` that pointer reverse-resolved to its `animation_table_ptrs1` index (40 walking, 41 sprinting, 42 running, 107 walking_unarmed — map via `src/game/initanitable.c`). `GE_D193A_CHR=` restricts to one chrnum. **This probe found D209**: Cradle showed `tier=1` (RUN) with `aidx=40/107` (walk anims) on every sample. | **live** (D193/D209) | | `GE_D193B` | `src/game/model.c` (`sub_GAME_7F06D3F4`, `#ifdef PORT`) | Rate-limited (1/97) raw anim root-motion decode trace (D193): `joint=` / `flip=` / `base=` mtx channel index / `frame=` / `tmp=` decoded s16 translation triple from the anim bitstream / `angle=` / `anim` ptr / `bd=`+`bs=` the D32 u32 bitDescriptors/bitStream addresses / `njoints`. M-80 Facility: `base=0`, `angle=0` **always** (root-motion facing delta never non-zero — top lead), `tmp` ≈ (±small, ~1086 hip-height, ±small). Compare `tmp`/`angle` magnitudes against a clean N64 decomp build of the same anim+frame. | **live** (D193) | +| `GE_D250` | `src/boss.c` (`bossMainloop`, wraps `lvlRender()`, `#ifdef PORT`) | Per-wall-second line: `[D250] lvlRender avg=Nus n=M` — average + count of `lvlRender()` (DL-building: culling/animation/scene traversal) calls that wall-second, isolated from `gfx_run()`'s software-RSP interpretation cost (already covered by the existing "frame rendered in Nus" line). Added M-120 to chase D250 (fps stuck ~45-50 on Dam, ruled resolution/MSAA/vsync/build-flags out already) — found `lvlRender` itself is cheap (~0.5-1.5ms avg), so it is NOT the missing ~10-15ms/frame either; the still-unexplained cost must be elsewhere in the per-retrace-message loop (scheduler/thread round-trip, audio, or something not yet isolated by a targeted timer). Cheap; safe for a full playtest. | **live** (D250) | | `GE_D172` | `port/fast3d/gfx_pc.cpp` (`gfx_sp_tri1` — SETCOMBINE dedup log + non-LOD multitex tri dump; `#ifdef PORT`) | Particle magenta/cyan colour (D172). Logs each distinct SETCOMBINE + active cycletype, and — for a 2-cycle tri that consumes TEXEL1 with `tex_lod=0` and a distinct 2nd tile — the tile fast3d *samples* for each texunit vs what the DL *configured*. **Found D172**: 40/40 particle tris configured tile 1 @ tmem 392 (fire) but sampled tile 0 (smoke) → `smoke*smoke`. FIXED (`gfx_lod_tile_offset` `return rdp.tex_lod ? 0 : i`). Probe kept inert. | **live** (D172 FIXED, probe kept) | | `GE_DVM` | `src/game/gunfire.c` (`gunUpdateAndFire` gate dump + `gunRenderFirstPersonGunModels` render dump; `#ifdef PORT`) | 1P weapon viewmodel (D215). `[DVM]` line: the `field_87F` show/hide gate terms + `Gun_hand_without_item` sub-terms + `copy_of_body_obj_header` RootNode/Switches/numRecords. `[DVMr]` line: `87F` + `cmds_emitted` = gfx commands the weapon `subdraw()` produced (healthy ≈ 150; the D215 bug showed **1**). Rate-limited ~1/s per hand. **Found + verified D215** (`renderdata.flags` read 0 → all weapon DL nodes gated off). Probe kept inert. | **live** (D215 FIXED, probe kept) | | `GE_DTEX` | `port/fast3d/gfx_pc.cpp:1001` | Per-`import_texture` param log (dims / line / size / lod / gen_mipmaps). Used to root-cause RC2 and D159. Kept as an inert diagnostic. | **live** (RC2/RC3 not finished) | diff --git a/docs/dev/findings.md b/docs/dev/findings.md index 2936c17a..9af44016 100644 --- a/docs/dev/findings.md +++ b/docs/dev/findings.md @@ -527,7 +527,7 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121). | D247 | **Black bars top and bottom of screen — possible aspect-ratio defect (M-116, user QA report).** Uninvestigated. Context: the port currently renders native 4:3 (640×480); widescreen is a *parked proposal* (`docs/dev/WIDESCREEN-FOV-PLAN.md` — PD-parity native 16:9 render, needs rule-#2 sign-off for its game-code HUD wave), so if the user's window/display is wider than 4:3 and the present path letterboxes to preserve aspect, the bars are current intended behaviour rather than a bug. If they appear in a 4:3 window too, it is a real defect (framebuffer sized wrong vs window, `videoCreateFramebuffer(w,h,upscale,autoresize)` → `gfx_create_framebuffer`). | **NOT A BUG — confirmed faithful, unmodified N64 decomp behaviour, no code change made.** `GE_PCDUMP` captures (both against the pre-existing save and a fresh-EEPROM run, to rule out a stale `Screen` option from earlier test sessions) show the exact same inset on Frigate: real scene content occupies rows ~20–459 of a 640×483 capture (the 483 vs 480 is a separate, harmless 3-row capture-tool rounding quirk, not investigated further), i.e. roughly 220/240 of the vertical field — and `src/game/fr.h:34` defines `VIEWPORT_HEIGHT_DEFAULT_NTSC 220` (240 for the full field), consumed unmodified by `bondviewGetCurrentPlayerViewportHeight()` (`bondview2.c:7858`) as the **default in-game viewport height whenever `PLAYER_OPTION_SCREEN` is `SCREEN_SIZE_FULLSCREEN`** (the decomp's own default value, `options.c:128`) — `VIEWPORT_HEIGHT_FULLSCREEN` (304, no inset) is a red herring name; it's only reachable via the `cameraBufferToggle` branch, not normal solo play. This is GoldenEye 007's well-documented original TV-safe-area letterboxing, baked into ground-truth decomp constants with no `#ifdef PORT` anywhere near it — the N64 game genuinely doesn't fill the full field during normal gameplay. Ruled out a stale/leftover EEPROM `Screen=Wide/Cinema` setting from earlier QoL-testing sessions as an alternative explanation: a fresh EEPROM (default options) shows the identical inset. **No fix needed; this row closes.** If the user's window shows noticeably *thicker* bars than this ~8–9%-per-edge margin, or bars appear on the *sides* instead of top/bottom, that would be a genuinely different (and real) symptom worth reopening under a new label — but "thin bars top and bottom, present at any window size" is correct, original behaviour. Cross-ref D226 (separate, already-tracked HUD-scale QoL ask — unrelated mechanism, don't conflate). | | D248 | **Port runs a stable 30 FPS instead of 60 FPS game-wide (M-117, user asked to verify FPS after the D209 timing-keystone fixes).** The port's pacemaker (`port/src/libultra.c` `portTickThread`) posts a VI-retrace event at a true 60Hz (NTSC) cadence, so the halving had to be somewhere downstream of that. | **FIXED, root-caused to a genuine pointer-width ABI bug in `src/sched.c` (compiled for the PC build, not excluded).** `osScAddClient()` (`src/sched.c:187-199`) stashes a per-client "present every retrace vs. every other retrace" flag by writing into the *next array slot's* `.next` field (`c[1].next = next`) rather than adding a real struct member — `gfxClient` (`src/init.c:246`) is registered with `next=NULL` (send every retrace → 60Hz) and the audio client `g_AudioClient[0]` (`src/audi.c:441`) with a nonzero sentinel `1` (send every other retrace → 30Hz, its intended cadence). `__scHandleRetrace` (`src/sched.c:334`) reads that flag back with a hardcoded byte offset, `*((s32*)client + 2)` (2×`sizeof(s32)` = 8 bytes). On the N64 (32-bit pointers) `sizeof(OSScClient)` is exactly 8 bytes, so offset 8 correctly lands on `client[1].next` — matching the write. On this 64-bit port `sizeof(OSScClient)` is 16 bytes, so the same hardcoded 8-byte offset instead reads the low 32 bits of `client->msgQ` itself (always a real, non-NULL pointer) — the gfx client's flag reads as permanently "nonzero" and silently falls onto the audio client's every-other-frame path, halving the game's real render/tick cadence to 30Hz although the retrace pacemaker itself was always ticking at the correct 60Hz. Same D122/D126/D132/D209 bug class (32→64-bit pointer-width struct-size growth desyncing a hand-rolled offset), just in the scheduler instead of a ROM-serialized struct. **Fix (`#ifdef PORT`, N64 line kept verbatim under `#else`):** read the real field by indexing the struct (`client[1].next == 0`) instead of hardcoding a byte offset — this naturally scales with pointer width on either platform and is the direct decompilation of what `osScAddClient`'s write side already does. **Verified:** `Video.DisplayFPS=1` overlay (`port/src/optionsoverlay.c`, D213) read a rock-stable "30 FPS" on `-level_09` (BUNKER1) pre-fix and "60 FPS" post-fix, same build/scene, screenshots captured via `GE_PCDUMP`. Rebuilt clean (`ninja -j1`, pre-existing unrelated warnings only); `-level_09` and `-level_20` both ran 12-30s post-fix with no crash (`ge007.crash.log` absent). No game-code files touched beyond this one mechanical read (`src/sched.c` is compiled for the PC target per `CMakeLists.txt`'s `SRC_ENGINE` list, not one of the excluded os/io files) and the audio client's own flag/path is completely untouched, so `#ifdef PORT`-gated audio pacing (D204 tempo work) is unaffected. **Note for `docs/dev/UNLOCKED-FPS-PLAN.md`:** this settles that plan's Phase 0 open question — the ~30fps default was a real port bug, not original N64 behavior or an artifact of retrace-rate tracking sim speed; the plan's default-preset baseline should be re-measured at the corrected 60fps before Phase 1 pacing work resumes. Not yet done: a full `verify.sh sweep` across all 21 levels (only `-level_09`/`-level_20` spot-checked this session) and a live human playtest for feel (input latency, animation smoothness, any level-specific perf regression now that render work happens twice as often per second). | | D249 | **LOD/culling breaks down on large open levels (Streets, Egyptian named specifically) at *default* FOV — far-away geometry has visible culling issues (M-119, user QA report).** Distinct from **D222** (which is specifically high `Video.FovScale` breaking *near-screen-edge* culling on NPCs/objects — not implicated here, default FOV) and from **D218** (the fog/far-clip *tint* boundary at wide FOV — also not the same symptom). This report is at the stock FOV, on the game's two biggest/most-open outdoor-scale levels, affecting *far* geometry specifically — points at either (a) a portal/room-visibility BFS cutting off too aggressively at range on large multi-room layouts (same neighbourhood as D233/D234's near-camera portal-cull bugs — worth checking whether D233's `gfx_sp_tri1` w<0 trivial-reject fix, which only guarded *behind-camera* vertices, has a sibling far-plane/depth-range case), or (b) GE's own N64 LOD/detail-swap system (mip-tile / simple-model substitution at distance — see D218's still-open question of "does GE have a separate geometry/object LOD-swap distinct from `Visibility.FarFog`") not being ported faithfully, popping or dropping geometry instead of swapping detail level. **Second, separate ask bundled in the same report:** the user would like LOD **improved** in general (presumably distance-based detail transitions look rougher/more abrupt on PC than remembered) but explicitly wants this **gated behind a toggle** so the original N64-accurate LOD behaviour stays selectable ("in case you want old school graphics") — i.e. this is a QoL feature request layered on top of a correctness bug, not one fix. | OPEN — not investigated. Next: reproduce on Streets (`-level_20`) and Egyptian (`-level_08`, confirm level id) at default `Video.FovScale`; `GE_PCDUMP` a long sightline where geometry visibly drops/pops, cross-referencing whatever governs GE's LOD-tile selection (`gfx_lod_tile_offset` family, already touched by D172/D219) and the portal/room-visibility walk (D233/D234 neighbourhood) to determine which of (a)/(b) is actually firing before designing a fix or the requested toggle. | -| D250 | **FPS is inconsistent/low on many levels since the port started actually running at 60fps — drops to 20–40fps intermittently, described as worse than before (M-119, user QA report, follow-on from D248).** Very likely a direct consequence of **D248** shipping: the port's render+tick loop had been silently running at half rate (30Hz) for the entire life of the project (D248, M-118) — the *real* per-level CPU/GPU cost of rendering and simulating this port was always this high, it was simply invisible while D248 halved the work being asked of the hardware every second. D248's own write-up flagged this as an open risk ("any level-specific perf regression now that render work happens twice as often per second") and explicitly left a live playtest / perf pass as un-done. Not yet investigated which side (CPU sim, CPU fast3d command generation, or GPU draw) is the bottleneck, or whether it's uniform or level-specific (the user's report implies specific/intermittent, which fits a per-scene cost — draw-call count, overdraw, or a specific expensive subsystem — rather than a flat doubled baseline cost). **M-120: partial progress, real bottleneck not yet caught.** User report sharpened: ~45fps at 720p on a self-described high-end PC, present even outside of dedicated stress levels — worse than the coarse "many levels, intermittent" framing suggested. Two things ruled out this session: (1) **build flags are not the cause** — `build-pc/CMakeCache.txt` confirms `CMAKE_BUILD_TYPE=RelWithDebInfo` (`-O2 -DNDEBUG`) is the actual default (`CMakeLists.txt:75-76`, unconditional unless a cache already exists), matching what `./build-pc.sh` produces with no extra flags — a debug/`-O0` build is not the explanation. (2) **idle-load is not the bottleneck, at least not in this dev box:** `GE_D193=1` on `-level_09` (BUNKER1, small level) idles at a rock-steady `render=60 sim=60`, frame-render time ~2.5 µs·10^3 (2.5 ms); `-level_29` (STREETS, one of D249's flagged large/open levels) idles at `render=55-60 sim=60-62`, frame-render time 6-7 ms — both comfortably under the 16.7 ms/60fps budget with no catch-up clamp hits. **This does not reproduce the user's 45fps** — either the real cost only shows up under actual gameplay load (AI/combat/particles active, not an empty idle scene — matches D193's own "player fine, AI-driven cost is different" pattern) or it's resolution/GPU-fill-rate-bound in a way this box's small idle test window doesn't exercise (this session could not drive real keyboard/mouse input into the game to generate a loaded scene — no interactive input tooling available headlessly). Also spotted and ruled out in passing: the `D51 vi post` debug log firing every render frame in `port/src/libultra.c:781` is throttled to ~once/sec (`% 60 == 1`), not a per-frame cost — not the culprit, though it's a `TEMP D51` instrument that's been live since early porting and could be removed as cleanup. **Next (highest-value, needs the user's hands, not headless):** during a live play session where fps visibly tanks, run with `GE_D193=1` and capture a few seconds of its per-second `render=`/`sim=`/`clamped=` lines right at the slow moment — that alone tells us whether the *sim* side is what's slow (would show `sim<60`, meaning AI/physics is the cost) vs. the *render/GL* side (would show `sim=60` but `rendersecond.data(); } @@ -1054,8 +1058,14 @@ static void import_texture(int i, int tile, bool importReplacement) { * RC2 (mip-chain contamination -> over-tall upload) can be told apart from a * decode/row-swap bug. tile_h = base-tile height from SETTILESIZE; if the * computed upload height is much larger, the excess rows are LOD mip data. - * docs/dev/TEXTURE-GLITCH-ANALYSIS.md sec 6b. */ - if (getenv("GE_DTEX")) { + * docs/dev/TEXTURE-GLITCH-ANALYSIS.md sec 6b. + * D250: import_texture() runs on every texture bind -- an uncached + * getenv() here measured at ~50% of the hot render thread's total CPU + * time on a texture-heavy level (Dam), via a live WPR/xperf profile. + * Cache like every other env-gated probe in this codebase. */ + static int ge_dtex = -1; + if (ge_dtex < 0) ge_dtex = getenv("GE_DTEX") != NULL; + if (ge_dtex) { static int dtexCount = 0; if (dtexCount < 64) { const uint32_t row = rdp.texture_tile[tile].line_size_bytes; @@ -1078,7 +1088,9 @@ static void import_texture(int i, int tile, bool importReplacement) { } } - if (getenv("GE_TEXDUMP")) { + static int ge_texdump = -1; + if (ge_texdump < 0) ge_texdump = getenv("GE_TEXDUMP") != NULL; + if (ge_texdump) { static int tdc = 0; const uint16_t* pal = (const uint16_t*)rdp.palette; sysLogPrintf(LOG_NOTE, @@ -1106,7 +1118,9 @@ static void import_texture(int i, int tile, bool importReplacement) { * against the TEXEL1_bytes=448 field already proven out via the * gfx_sp_tri1 D172/D219 probe. */ const bool is_fire_bytes = (loaded_texture.size_bytes == 448); - if ((is_fire_bytes || tdc <= 400) && getenv("GE_TEXRAW")) { + static int ge_texraw = -1; + if (ge_texraw < 0) ge_texraw = getenv("GE_TEXRAW") != NULL; + if ((is_fire_bytes || tdc <= 400) && ge_texraw) { char nm[160]; snprintf(nm, sizeof nm, "texdump/r%03d_f%u_s%u_%ux%u.bin", tdc - 1, fmt, siz, tw, th); FILE* bf = fopen(nm, "wb"); @@ -1140,7 +1154,9 @@ static void import_texture(int i, int tile, bool importReplacement) { if (fmt_eff == G_IM_FMT_RGBA && siz == G_IM_SIZ_16b && loaded_texture.src_fmt == G_IM_FMT_CI) { #ifdef PORT - if (getenv("GE_D229")) { + static int ge_d229_a = -1; + if (ge_d229_a < 0) ge_d229_a = getenv("GE_D229") != NULL; + if (ge_d229_a) { static int n_ci8r = 0; if (n_ci8r++ < 8) sysLogPrintf(LOG_NOTE, "D229: RGBA16 tile over CI8 source -> ci8 import (addr=%p size=%u palidx=%u)", @@ -1816,7 +1832,9 @@ static void gfx_sp_tri1(uint8_t vtx1_idx, uint8_t vtx2_idx, uint8_t vtx3_idx, bo * texture identity so one Frigate capture pins whether TEXEL1 * resolves to the same image/region as TEXEL0 or drifts into * other TMEM content (the green). */ - if (getenv("GE_D229") && use_2cyc && comb->used_textures[0] && comb->used_textures[1]) { + static int ge_d229_b = -1; + if (ge_d229_b < 0) ge_d229_b = getenv("GE_D229") != NULL; + if (ge_d229_b && use_2cyc && comb->used_textures[0] && comb->used_textures[1]) { static int d229x = 0; static int d229_total = 0; d229_total++; @@ -1859,7 +1877,9 @@ static void gfx_sp_tri1(uint8_t vtx1_idx, uint8_t vtx2_idx, uint8_t vtx3_idx, bo * formats - tile 0 IA8 smoke, tile 1 RGBA16 fire @ tmem 0x188. Dump both * texunits' tile state whenever a 2-cycle tri actually consumes TEXEL1, so * one Silo capture pins whether TEXEL1 resolves to the right tmem/format. */ - if (getenv("GE_D172") && use_2cyc && comb->used_textures[1] && !rdp.tex_lod) { + static int ge_d172_a = -1; + if (ge_d172_a < 0) ge_d172_a = getenv("GE_D172") != NULL; + if (ge_d172_a && use_2cyc && comb->used_textures[1] && !rdp.tex_lod) { const uint32_t fi = rdp.first_tile_index; /* the tile fast3d will actually SAMPLE for each texunit */ const uint32_t s0 = fi + gfx_lod_tile_offset(0); @@ -3046,7 +3066,9 @@ static void gfx_run_dl(Gfx* cmd) { * (explosion.c g_ExplosionDisplayLists[]) set a 2-cycle * combine but never set cycletype - this tells us what * cycletype fast3d has when they replay. */ - if (getenv("GE_D172")) { + static int ge_d172_b = -1; + if (ge_d172_b < 0) ge_d172_b = getenv("GE_D172") != NULL; + if (ge_d172_b) { static uint64_t d172seen[64]; static int d172cnt = 0; uint64_t key = ((uint64_t)(uint32_t)cmd->words.w0 << 32) | (uint32_t)cmd->words.w1; diff --git a/port/fast3d/gfx_sdl2.cpp b/port/fast3d/gfx_sdl2.cpp index 2386cf07..a43552a7 100644 --- a/port/fast3d/gfx_sdl2.cpp +++ b/port/fast3d/gfx_sdl2.cpp @@ -409,7 +409,13 @@ static inline void sync_framerate_with_timer(void) { // We want to exit a bit early, so we can busy-wait the rest to never miss the deadline left -= 15000UL; if (left > 0) { - sysSleep(left); + /* D250: `left` is in 100ns units (qpc_to_100ns); sysSleep() takes + * microseconds. Passing it unconverted slept ~10x too long every + * time this branch fired (e.g. an intended 2ms sleep became a real + * ~20ms one), silently eating the rest of the frame budget whenever + * per-frame work left little slack -- a resolution/GPU-independent + * frame-pacing bug, not a real render cost. */ + sysSleep((uint32_t)(left / 10)); } do { diff --git a/src/boss.c b/src/boss.c index 3412c57b..f1c45aca 100644 --- a/src/boss.c +++ b/src/boss.c @@ -2,6 +2,7 @@ #include #ifdef PORT #include +#include #endif #include "bondview.h" #include @@ -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. diff --git a/tools_pc/perf.ps1 b/tools_pc/perf.ps1 new file mode 100644 index 00000000..d9827b3c --- /dev/null +++ b/tools_pc/perf.ps1 @@ -0,0 +1,130 @@ +<# + perf.ps1 - sister script to debug.ps1: launch the PC port under an ETW + trace (xperf, part of the Windows Performance Toolkit) so a bad-fps + playtest always leaves a CPU profile, not just a "felt slow" report. + + Requires an ELEVATED PowerShell/cmd (xperf needs SeSystemProfilePrivilege). + Re-launch this script itself as admin if it complains. + + Usage (from repo root, elevated): + .\tools_pc\perf.ps1 # front-end / menu playtest + .\tools_pc\perf.ps1 -level_33 # boot straight into a level (Dam) + .\tools_pc\perf.ps1 -level_33 -Seconds 30 # auto-stop after 30s instead of waiting for exit + .\tools_pc\perf.ps1 -NoBuild -NoSymbols # skip rebuild + skip MS symbol download (faster) + + Produces, under perf_captures\\: + trace.etl - raw ETW trace (open in WPA for the full GUI view) + cswitch_thread.csv - per-thread CPU time (xperf -a cswitch -thread -process) + profile_detail.csv - per-module CPU sample weight, per process + summary.txt - tracerpt event-count summary + and prints a quick top-offenders readout (busiest thread, busiest modules) + straight to the console so most sessions won't need WPA at all. + + Symbol resolution (-Symbols, off by default): downloads Microsoft's public + PDBs for system DLLs (msvcrt.dll, ntdll.dll, ...) so hot functions inside + them resolve by name instead of just module -- this is what caught the + D250 getenv() bug. Slow on first run (network), fast after (local cache + under perf_captures\symcache\). Our own ge007.x86_64.exe uses DWARF debug + info (GCC -g), which xperf/WPA cannot read regardless of -Symbols -- that + part of any stack always shows as the raw module name, not a function. +#> +[CmdletBinding()] +param( + [int]$Seconds = 0, # 0 = wait for the game to exit on its own + [switch]$NoBuild, + [switch]$Symbols, + [string]$Xperf = "C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\xperf.exe", + [Parameter(ValueFromRemainingArguments = $true)] + [string[]]$GameArgs +) + +$ErrorActionPreference = "Stop" + +$isAdmin = ([Security.Principal.WindowsPrincipal][Security.Principal.WindowsIdentity]::GetCurrent()).IsInRole([Security.Principal.WindowsBuiltInRole]::Administrator) +if (-not $isAdmin) { throw "perf.ps1 needs an elevated shell (xperf requires SeSystemProfilePrivilege) - re-run from an admin PowerShell/cmd." } +if (-not (Test-Path $Xperf)) { throw "xperf not found at $Xperf (pass -Xperf ; it ships with the Windows Performance Toolkit / Windows SDK)" } + +# The exe links MSYS2 mingw64 DLLs (SDL2, libgcc, libstdc++, libwinpthread, +# zlib). An elevated PowerShell doesn't have these on PATH and the game dies +# at startup with 0xc0000135 (DLL not found) -- same fix as debug.ps1. +$MingwBin = "C:\msys64\mingw64\bin" +if ((Test-Path $MingwBin) -and (($env:PATH -split ';') -notcontains $MingwBin)) { + $env:PATH = "$MingwBin;$env:PATH" +} + +$exe = "build-pc\ge007.x86_64.exe" +if (-not $NoBuild) { + Write-Host "building (bash build-pc.sh ntsc-final) - pass -NoBuild to skip" -ForegroundColor DarkGray + & "C:\msys64\usr\bin\bash.exe" -lc "cd '$($PWD -replace '\\','/')' && export PATH=/c/msys64/mingw64/bin:`$PATH && ./build-pc.sh ntsc-final" + if ($LASTEXITCODE -ne 0) { throw "build failed" } +} +if (-not (Test-Path $exe)) { throw "no exe - build the port: bash build-pc.sh ntsc-final" } + +$stamp = Get-Date -Format "yyyyMMdd_HHmmss" +$outDir = "perf_captures\$stamp" +New-Item -ItemType Directory -Force -Path $outDir | Out-Null +$etl = Join-Path $outDir "trace.etl" + +Write-Host "starting xperf trace (CPU sampling + context switches)" -ForegroundColor Cyan +& $Xperf -on PROC_THREAD+LOADER+CSWITCH+DISPATCHER+PROFILE -stackwalk PROFILE +if ($LASTEXITCODE -ne 0) { throw "xperf -start failed" } + +try { + Write-Host "launching $exe $GameArgs" -ForegroundColor Green + $proc = Start-Process -FilePath $exe -ArgumentList $GameArgs -PassThru + + if ($Seconds -gt 0) { + Write-Host "capturing for $Seconds s (play now) ..." -ForegroundColor Yellow + Start-Sleep -Seconds $Seconds + if (-not $proc.HasExited) { Stop-Process -Id $proc.Id -Force } + } else { + Write-Host "capturing until the game exits (close the window when done) ..." -ForegroundColor Yellow + $proc.WaitForExit() + } +} finally { + Write-Host "stopping xperf trace -> $etl" -ForegroundColor Cyan + & $Xperf -stop -d $etl +} + +if (-not (Test-Path $etl)) { throw "trace file was not written - xperf -stop likely errored above" } + +$symArgs = @() +if ($Symbols) { + $symCache = "perf_captures\symcache" + New-Item -ItemType Directory -Force -Path $symCache | Out-Null + $env:_NT_SYMBOL_PATH = "srv*$symCache*https://msdl.microsoft.com/download/symbols" + $env:_NT_SYMCACHE_PATH = $symCache + $symArgs = @("-symbols") + Write-Host "resolving symbols against Microsoft's public server (first run is slow)" -ForegroundColor DarkGray +} + +Write-Host "`nanalyzing trace ..." -ForegroundColor Cyan +& "C:\Windows\System32\tracerpt.exe" $etl -summary (Join-Path $outDir "summary.txt") -y | Out-Null +& $Xperf -i $etl @symArgs -o (Join-Path $outDir "cswitch_thread.csv") -a cswitch -thread -process +& $Xperf -i $etl @symArgs -o (Join-Path $outDir "profile_detail.csv") -a profile -detail + +# ---- Quick top-offenders readout ------------------------------------------- +$procRow = Select-String -Path (Join-Path $outDir "cswitch_thread.csv") -Pattern "ge007\.x86_64\.exe" | Select-Object -First 1 +Write-Host "`n===================== RESULT =====================" -ForegroundColor Yellow +if ($procRow) { Write-Host "process total CPU time: $($procRow.Line.Trim())" } + +Write-Host "`n-- busiest ge007 threads (CPU us) --" -ForegroundColor Red +Get-Content (Join-Path $outDir "cswitch_thread.csv") | + Select-String -Pattern "ge007\.x86_64\.exe.*,\s*\d+\s*$" | + ForEach-Object { $_.Line.Trim() } | + Sort-Object { [int]($_ -replace ',.*$', '') } -Descending | + Select-Object -First 8 + +Write-Host "`n-- busiest modules inside ge007 (sample weight) --" -ForegroundColor Red +Get-Content (Join-Path $outDir "profile_detail.csv") | + Select-String -Pattern "^ge007\.x86_64\.exe" | + ForEach-Object { + $f = $_.Line -split "," + [PSCustomObject]@{ Weight = [long]($f[1].Trim()); Pct = $f[2].Trim(); Module = $f[3].Trim() } + } | Sort-Object Weight -Descending | Select-Object -First 12 | + Format-Table -AutoSize + +Write-Host "`nraw data: $outDir\ (open trace.etl in WPA for the full GUI view)" -ForegroundColor DarkGray +if (-not $Symbols) { + Write-Host "re-run with -Symbols to resolve system-DLL function names (e.g. this is how D250's getenv() bug was found)" -ForegroundColor DarkGray +}