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>
2f4ed244ea