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 <stdlib.h> 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) <noreply@anthropic.com>
Co-authored-by: GitHub Copilot <copilot@github.com>
This commit is contained in:
co-authored by
Claude Opus 5
GitHub Copilot
Claude Opus 5
GitHub Copilot
parent
9c67dddd83
commit
2f4ed244ea
@@ -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
|
||||
|
||||
@@ -20,6 +20,7 @@
|
||||
#include "MemoryManager.hpp"
|
||||
#include "DirectX.hpp"
|
||||
#include "FileIO.hpp"
|
||||
#include <stdlib.h> // [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 && dwSeen<dwCount; b-- )
|
||||
{
|
||||
DWORD dwTake=s_adwFpsHist[b];
|
||||
if( !dwTake )
|
||||
continue;
|
||||
if( dwTake>dwCount-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_nWorst<MAX_WORST )
|
||||
s_afWorst[s_nWorst++] = fMS;
|
||||
@@ -930,12 +1052,12 @@ static void GOS_LogFrameRate( float fFrameRate )
|
||||
|
||||
float fAvgMS = s_fSumMS/(float)s_nFrames;
|
||||
float fAvgFPS = 1000.0f/fAvgMS;
|
||||
float fMinFPS = 1000.0f/s_fMaxMS;
|
||||
|
||||
// 1% low: mean of the worst 1% of frames (at least one).
|
||||
int nLow = s_nFrames/100;
|
||||
if( nLow<1 )
|
||||
nLow = 1;
|
||||
// 5% low, not 1%: at 60 samples a "1% low" is a single frame, which is just the
|
||||
// worst-frame column restated. Worst 3-of-60 is a number that actually differs.
|
||||
int nLow = s_nFrames/20;
|
||||
if( nLow<3 )
|
||||
nLow = 3;
|
||||
if( nLow>s_nWorst )
|
||||
nLow = s_nWorst;
|
||||
float fLowSum=0.0f;
|
||||
@@ -948,23 +1070,26 @@ static void GOS_LogFrameRate( float fFrameRate )
|
||||
for( int k=0; k<s_nWorst; k++ )
|
||||
if( s_afWorst[k]>fAvgMS*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;
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user