From 2f4ed244eacdef2e41ba797e216d9645f044a5d6 Mon Sep 17 00:00:00 2001 From: RT Date: Sat, 25 Jul 2026 18:38:48 -0500 Subject: [PATCH] Fix -fps logger measuring its own overhead; buffer output, fix percentiles First real run of -fps (222 seconds, 4-monitor bench, in-mission) showed a rock-solid 60.0 fps average but a worst frame of ~24ms in 82% of seconds, with a median of 24.4ms and a minimum of 23.2ms. That regularity was the tell: 60Hz vsync intervals are 16.7 / 33.3 / 50.0 ms, so 24ms is not a multiple of anything and had no business recurring once per second with that consistency. Cause: the logger was measuring itself. The per-second line was written straight to the file with WriteFile on the render thread, and the frame duration is recorded BEFORE the line is emitted -- so the write's cost landed in the *next* frame's measurement, which belongs to the next second's bucket. Result: exactly one inflated frame per second, indefinitely. Holding the handle open (as the first version did) was not enough; a single WriteFile is still several milliseconds when something like antivirus is in the path. Three fixes: 1. Buffered output. Lines accumulate in a 128 KB static buffer (~2000 rows, about 33 minutes at one row per second) and are flushed only when the buffer fills or at exit via atexit(). A normal measurement session now performs no file writes at all while running. Trade-off, deliberately accepted: a hard crash loses the un-flushed tail. gos-displays.txt remains the crash-survivable log; gos-fps.txt is a measurement instrument and must not perturb what it measures. 2. Meaningful percentiles. A "1% low" over 60 samples per second computes nFrames/100 = 0, which was clamped to 1 -- so the column was literally 1000/worst_frame, i.e. the worst-frame column restated in different units. Verified against the log: worst 24.1ms -> 41.5 fps, exactly the "1% low" printed. Per-second is now a 5% low (worst 3 of 60), which is a number that actually differs from the worst frame. True whole-session 1% and 0.1% lows are computed at exit from a 0.5ms-bucket frame time histogram (2000 buckets, 0-1000ms) and printed in a new session summary along with total frames, elapsed time, average, and total hitches. The histogram gives exact-enough percentiles over an entire session without retaining every frame time. 3. Carry-over. A single frame longer than one second (a level load: the log shows 4338ms and 4799ms frames) left the accumulator above the 1000ms threshold, so the next few frames each emitted their own bogus one-frame row -- visible in the log as rows reporting "1 frame, 1339 fps". The excess is now discarded. Also adds #include to WinMain.cpp for atexit(); it was not reachable through pch.hpp. GOS_FpsAtExit is declared __cdecl: GameOS builds with /Gz, which makes __stdcall the default calling convention, but atexit() takes a __cdecl callback -- without it VC6 rejects the call with C2664. What the run did establish, and still stands: 60 frames per second sustained for ~150 seconds with no rhythmic multi-hitch pattern, so the mode 4 split-MFD stutter fix (0a657b59) is holding. Genuine dropped frames (>40ms) occurred in 18% of seconds, including clusters of 80-90ms; those are real and unaffected by this fix. Re-measure after this change to see the true baseline. CLAUDE.md STEP 10 updated: the previous claim that holding the handle open kept the logger from perturbing the measurement was wrong, and is replaced with what was actually observed. Co-authored-by: Claude Opus 5 (Anthropic) Co-authored-by: GitHub Copilot --- CLAUDE.md | 25 ++- .../CoreTech/Libraries/GameOS/WinMain.cpp | 183 +++++++++++++++--- 2 files changed, 173 insertions(+), 35 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index cfe27b3e..e4668dc2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -961,12 +961,25 @@ was no way to see any of it. **Fixing that visibility was what unblocked the who / `HSH_HRName()` (27 `DDERR_*` codes decoded by name). Appends to the same file; each line is written and flushed individually so **the log survives a crash**. - **`gos-fps.txt`** — new **`-fps`** switch (`WinMain.cpp` `GOS_LogFrameRate`, hooked onto the - existing `frameRate` global). Per-second: frames, avg fps, **1% low**, worst frame in ms, - and a count of frames over 2x average ("hitches"). Works in **Release** — the engine's own - `AddDebugData("FrameRate")` is `#ifdef LAB_ONLY` (`MWMission.cpp`) so it only exists in - `MW4pro.exe`. Off unless `-fps` is given (a global read + branch when absent, no file - created). Handle is held open for the process lifetime so the once-per-second write does not - put an unpredictable syscall on the render thread — the tool must not perturb what it measures. + existing `frameRate` global). Per-second: frames, avg fps, **5% low**, worst frame in ms, + and a count of frames over 2x average ("hitches"), plus a **session summary** at exit with + true whole-session 1% / 0.1% lows (computed from a 0.5 ms-bucket histogram). Works in + **Release** — the engine's own `AddDebugData("FrameRate")` is `#ifdef LAB_ONLY` + (`MWMission.cpp`) so it only exists in `MW4pro.exe`. Off unless `-fps` is given (a global + read + branch when absent, no file created). + - ⚠️ **Lesson from the first real run: the instrument was measuring itself.** The original + version wrote one line per second straight to the file. The frame time is recorded + *before* the line is emitted, so the `WriteFile` cost landed in the **next** frame — + producing exactly one inflated frame every second (median worst-frame 24.4 ms against a + 16.7 ms vsync interval, in 82% of seconds). Output is now buffered in memory and flushed + only when full or at exit (`atexit`), so a normal session performs no writes while + running. Trade-off: a hard crash loses the un-flushed tail — `gos-displays.txt` is the + crash-survivable log, this one is a measurement instrument. + - Also fixed: a "1% low" over 60 samples/sec degenerates to `nFrames/100 = 0` → clamped to + 1 → literally the worst frame restated, so the column was redundant. Per-second is now a + 5% low (worst 3-of-60); true 1% / 0.1% lows are in the session summary. And a single + frame longer than a second (a level load) no longer spills into following buckets and + emits a run of bogus one-frame rows. ### ✅ Crash-safety fix (independent of everything else, worth keeping) `hsh_initialized` was set **unconditionally** after panel init. A failed panel therefore left diff --git a/Gameleap/code/CoreTech/Libraries/GameOS/WinMain.cpp b/Gameleap/code/CoreTech/Libraries/GameOS/WinMain.cpp index 4838079d..4b54f3aa 100644 --- a/Gameleap/code/CoreTech/Libraries/GameOS/WinMain.cpp +++ b/Gameleap/code/CoreTech/Libraries/GameOS/WinMain.cpp @@ -20,6 +20,7 @@ #include "MemoryManager.hpp" #include "DirectX.hpp" #include "FileIO.hpp" +#include // [fpslog] atexit() for the frame pacing summary #include "ControlManager.hpp" #include "LocalizationManager.hpp" #include "Time.hpp" @@ -842,7 +843,7 @@ HRESULT App_Render( LPDIRECT3DDEVICE7 pd3dDevice,LPDIRECTDRAWSURFACE7 pddsTextur // -// [fpslog] Per-second frame pacing report, written to gos-fps.txt next to the executable. +// [fpslog] Frame pacing report, written to gos-fps.txt next to the executable. // // Off unless the -fps switch is given, so a normal pod run does no extra work at all. // Set from MW4Application's command-line parser. @@ -853,24 +854,44 @@ int g_nFpsLog = 0; // MW4pro.exe. This works in Release builds, which is what actually runs on the pods. // // Average FPS on its own hides stutter: 60 fps average is indistinguishable from 60 fps -// with a dropped frame every second. So this also reports the slowest single frame and a -// 1% low (the mean of the worst 1% of frames in that second), which is where rhythmic -// hitching shows up, plus a count of frames that took more than twice the average. +// with a dropped frame every second. So this also reports the slowest frames, which is +// where rhythmic hitching shows up. // -static void GOS_FpsWriteLine( const char* pszLine ) +// IMPORTANT - why the output is buffered: +// The first version wrote one line per second straight to the file. That put a WriteFile +// on the render thread every second, and its cost landed in the NEXT frame's measurement +// (the frame time is recorded before the line is emitted). The result was exactly one +// inflated frame per second, forever - the tool was reporting its own overhead as the +// game's worst frame. Everything is now accumulated in memory and flushed only when the +// buffer fills or at exit, so a normal session performs no writes at all while running. +// Trade-off: a hard crash loses the un-flushed tail. gos-displays.txt is the +// crash-survivable log; this one is a measurement instrument. +// +static char s_szFpsBuf[131072]; // ~2000 lines, about 33 minutes at 1 line/sec +static int s_nFpsBufUsed = 0; +static HANDLE s_hFpsFile = INVALID_HANDLE_VALUE; +static int s_bFpsAtExit = 0; + +// Whole-session frame time histogram in 0.5 ms buckets (0 - 1000 ms). Lets the true +// session-wide percentiles be computed at exit without retaining every frame time. +#define FPS_HIST_BUCKETS 2000 +static DWORD s_adwFpsHist[FPS_HIST_BUCKETS]; +static DWORD s_dwFpsFrames = 0; +static double s_dFpsTotalMS = 0.0; +static DWORD s_dwFpsHitches = 0; + +static void GOS_FpsFlush( void ) { - // The handle is held open for the life of the process. Opening and closing the file - // every second would put a syscall of unpredictable latency (worse with antivirus or - // a network path) on the render thread - which is exactly what this code is trying to - // measure. Writes still survive a crash, because WriteFile hands the data to the OS - // cache rather than a CRT buffer. - static HANDLE s_hFile=INVALID_HANDLE_VALUE; - char szDir[MAX_PATH]; - char szPath[MAX_PATH]; DWORD dwWritten=0; - if( s_hFile==INVALID_HANDLE_VALUE ) + if( s_nFpsBufUsed<=0 ) + return; + + if( s_hFpsFile==INVALID_HANDLE_VALUE ) { + char szDir[MAX_PATH]; + char szPath[MAX_PATH]; + szDir[0]='\0'; GetModuleFileNameA( NULL, szDir, sizeof(szDir) ); char* pSlash=strrchr( szDir, '\\' ); @@ -880,19 +901,104 @@ static void GOS_FpsWriteLine( const char* pszLine ) szDir[0]='\0'; sprintf( szPath, "%sgos-fps.txt", szDir ); - // FILE_SHARE_READ so the file can be tailed while the game is running. - s_hFile=CreateFileA( szPath, GENERIC_WRITE, FILE_SHARE_READ, NULL, - CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL ); - if( s_hFile==INVALID_HANDLE_VALUE ) + // FILE_SHARE_READ so the file can be read while the game is still running. + s_hFpsFile=CreateFileA( szPath, GENERIC_WRITE, FILE_SHARE_READ, NULL, + CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL ); + if( s_hFpsFile==INVALID_HANDLE_VALUE ) + { + s_nFpsBufUsed=0; // drop it rather than retry every second return; + } } - WriteFile( s_hFile, pszLine, (DWORD)strlen(pszLine), &dwWritten, NULL ); + WriteFile( s_hFpsFile, s_szFpsBuf, (DWORD)s_nFpsBufUsed, &dwWritten, NULL ); + s_nFpsBufUsed=0; +} + +// Mean frame time (ms) of the slowest dwCount frames of the whole session. +static double GOS_FpsSlowestMean( DWORD dwCount ) +{ + double dSum=0.0; + DWORD dwSeen=0; + int b; + + if( dwCount<1 ) + dwCount=1; + + for( b=FPS_HIST_BUCKETS-1; b>=0 && dwSeendwCount-dwSeen ) + dwTake=dwCount-dwSeen; + dSum += (((double)b+0.5)/2.0)*(double)dwTake; + dwSeen += dwTake; + } + return dwSeen ? (dSum/(double)dwSeen) : 0.0; +} + +static void GOS_FpsAppend( const char* pszLine ) +{ + int nLen=(int)strlen(pszLine); + + if( nLen<=0 ) + return; + if( s_nFpsBufUsed+nLen > (int)sizeof(s_szFpsBuf) ) + GOS_FpsFlush(); // buffer full: one write, rarely + if( s_nFpsBufUsed+nLen > (int)sizeof(s_szFpsBuf) ) + return; // still no room: give up quietly + + memcpy( s_szFpsBuf+s_nFpsBufUsed, pszLine, nLen ); + s_nFpsBufUsed += nLen; +} + +// NOTE: must be __cdecl. GameOS builds with /Gz (__stdcall by default), but atexit() +// takes a __cdecl callback, so without this the compiler rejects it with C2664. +static void __cdecl GOS_FpsAtExit( void ) +{ + char szLine[256]; + + if( s_dwFpsFrames ) + { + // True session-wide percentiles, which a per-second bucket cannot give: + // 1% of 60 frames is 0, so a "1% low" computed per second degenerates into + // "the single worst frame". Over a whole session it is meaningful. + double dAvgMS = s_dFpsTotalMS/(double)s_dwFpsFrames; + double dOnePct = GOS_FpsSlowestMean( s_dwFpsFrames/100 ); + double dTenthPct= GOS_FpsSlowestMean( s_dwFpsFrames/1000 ); + + GOS_FpsAppend( "\r\n" ); + GOS_FpsAppend( "session summary\r\n" ); + GOS_FpsAppend( "---------------\r\n" ); + sprintf( szLine, " frames : %lu\r\n", (unsigned long)s_dwFpsFrames ); + GOS_FpsAppend( szLine ); + sprintf( szLine, " elapsed : %.1f s\r\n", s_dFpsTotalMS/1000.0 ); + GOS_FpsAppend( szLine ); + sprintf( szLine, " average : %.1f fps (%.2f ms)\r\n", + (dAvgMS>0.0)?1000.0/dAvgMS:0.0, dAvgMS ); + GOS_FpsAppend( szLine ); + sprintf( szLine, " 1%% low : %.1f fps (%.2f ms)\r\n", + (dOnePct>0.0)?1000.0/dOnePct:0.0, dOnePct ); + GOS_FpsAppend( szLine ); + sprintf( szLine, " 0.1%% low : %.1f fps (%.2f ms)\r\n", + (dTenthPct>0.0)?1000.0/dTenthPct:0.0, dTenthPct ); + GOS_FpsAppend( szLine ); + sprintf( szLine, " frames over 2x avg: %lu\r\n", (unsigned long)s_dwFpsHitches ); + GOS_FpsAppend( szLine ); + } + + GOS_FpsFlush(); + if( s_hFpsFile!=INVALID_HANDLE_VALUE ) + { + CloseHandle( s_hFpsFile ); + s_hFpsFile=INVALID_HANDLE_VALUE; + } } static void GOS_LogFrameRate( float fFrameRate ) { - enum { MAX_WORST = 64 }; // >= 1% of any plausible per-second frame count + enum { MAX_WORST = 64 }; static float s_afWorst[MAX_WORST]; // longest frames this second, descending ms static int s_nWorst = 0; static float s_fAccumMS= 0.0f; @@ -908,6 +1014,12 @@ static void GOS_LogFrameRate( float fFrameRate ) if( fFrameRate<=0.0f ) return; + if( !s_bFpsAtExit ) + { + s_bFpsAtExit=1; + atexit( GOS_FpsAtExit ); // flush the buffer + write the summary + } + float fMS = 1000.0f/fFrameRate; s_nFrames++; @@ -916,6 +1028,16 @@ static void GOS_LogFrameRate( float fFrameRate ) if( fMS>s_fMaxMS ) s_fMaxMS = fMS; + // Whole-session histogram (0.5 ms buckets, saturating at the top bucket). + int nBucket=(int)(fMS*2.0f); + if( nBucket<0 ) + nBucket=0; + if( nBucket>=FPS_HIST_BUCKETS ) + nBucket=FPS_HIST_BUCKETS-1; + s_adwFpsHist[nBucket]++; + s_dwFpsFrames++; + s_dFpsTotalMS += fMS; + // Maintain the longest frames of this second, sorted longest-first. if( s_nWorsts_nWorst ) nLow = s_nWorst; float fLowSum=0.0f; @@ -948,23 +1070,26 @@ static void GOS_LogFrameRate( float fFrameRate ) for( int k=0; kfAvgMS*2.0f ) nHitch++; + s_dwFpsHitches += nHitch; if( s_nSecond==0 ) - GOS_FpsWriteLine( " sec frames avg fps 1% low worst frame hitches\r\n" - " --- ------ ------- ------ ----------- -------\r\n" ); + GOS_FpsAppend( " sec frames avg fps 5% low worst frame hitches\r\n" + " --- ------ ------- ------ ----------- -------\r\n" ); sprintf( szLine, "%5d %6d %8.1f %8.1f %8.1f ms %s%d\r\n", s_nSecond, s_nFrames, fAvgFPS, fLowFPS, s_fMaxMS, nHitch ? "<-- " : "", nHitch ); - GOS_FpsWriteLine( szLine ); + GOS_FpsAppend( szLine ); s_nSecond++; s_nFrames = 0; s_nWorst = 0; s_fSumMS = 0.0f; s_fMaxMS = 0.0f; + // A single frame longer than a second (a level load) must not spill into the next + // buckets and emit a run of bogus one-frame rows, which is what used to happen. s_fAccumMS-= 1000.0f; - if( s_fAccumMS<0.0f ) + if( s_fAccumMS<0.0f || s_fAccumMS>=1000.0f ) s_fAccumMS = 0.0f; }