Files
goldeneye-pc-port/tools_pc/perf.ps1
T
James Dansereau 70bc9d65b5 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.
2026-09-13 09:33:36 -04:00

131 lines
6.6 KiB
PowerShell

<#
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\<timestamp>\:
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 <path>; 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
}