From dd8307ef4c32362b50ca8591b6b5a476c9bed009 Mon Sep 17 00:00:00 2001 From: Aciz Date: Sun, 11 Aug 2024 16:42:12 +0300 Subject: [PATCH 1/4] Improve timedemo output + add benchmark command Timedemo now outputs time, frames, min/max/avg fps, 99th pct min and 99.9th pct min fps Added benchmark command - wrapper command that enables timedemo and plays back specified demo --- src/client/cl_cgame.c | 10 ++-- src/client/cl_main.c | 130 ++++++++++++++++++++++++++++++++++++++++-- src/client/client.h | 14 ++++- 3 files changed, 141 insertions(+), 13 deletions(-) diff --git a/src/client/cl_cgame.c b/src/client/cl_cgame.c index c8e90e96..3fe62a0f 100644 --- a/src/client/cl_cgame.c +++ b/src/client/cl_cgame.c @@ -1519,7 +1519,7 @@ static void CL_FirstSnapshot( void ) { cl.serverTimeDelta = cl.snap.serverTime - cls.realtime; cl.oldServerTime = cl.snap.serverTime; - clc.timeDemoBaseTime = cl.snap.serverTime; + clc.timedemo.timeDemoBaseTime = cl.snap.serverTime; // if this is the first frame of active play, // execute the contents of activeAction now @@ -1695,11 +1695,11 @@ void CL_SetCGameTime( void ) { // while a normal demo may have different time samples // each time it is played back if ( com_timedemo->integer ) { - if ( !clc.timeDemoStart ) { - clc.timeDemoStart = Sys_Milliseconds(); + if ( !clc.timedemo.timeDemoStart ) { + clc.timedemo.timeDemoStart = Sys_Microseconds(); } - clc.timeDemoFrames++; - cl.serverTime = clc.timeDemoBaseTime + clc.timeDemoFrames * 50; + clc.timedemo.timeDemoFrames++; + cl.serverTime = clc.timedemo.timeDemoBaseTime + clc.timedemo.timeDemoFrames * 50; } //while ( cl.serverTime >= cl.snap.serverTime ) { diff --git a/src/client/cl_main.c b/src/client/cl_main.c index ada63b92..919ec55c 100644 --- a/src/client/cl_main.c +++ b/src/client/cl_main.c @@ -750,6 +750,112 @@ CLIENT SIDE DEMO PLAYBACK ======================================================================= */ +/* +==================== +CL_StartBenchmark_f +==================== +*/ +static void CL_StartBenchmark_f(void) { + if (Cmd_Argc() < 2) { + Com_Printf("benchmark \n"); + return; + } + + // enable timedemo if it isn't set already (and keep track if we changed the value, so we can restore it) + if (!Cvar_VariableIntegerValue("timedemo")) { + Cvar_Set("timedemo", "1"); + cls.resetTimedemoCvar = qtrue; + } + + cls.benchmarking = qtrue; + Cbuf_ExecuteText(EXEC_APPEND, va("demo %s", Cmd_Argv(1))); +} + +/* +================= +CL_CompareFrametimes +================= +*/ +static int CL_CompareFrametimes(const void *a, const void *b) { + const uint32_t arg1 = *(uint32_t *)a; + const uint32_t arg2 = *(uint32_t *)b; + + if (arg1 > arg2) { + return 1; + } else if (arg2 > arg1) { + return -1; + } else { + return 0; + } +} + +/* +================= +CL_TimedemoResults +================= +*/ +static void CL_TimedemoResults(void) { + int64_t time; + int i, numFrames; + uint32_t sortedFrametimes[MAX_TIMEDEMO_FRAMES]; + int onePercentIdx, pointOnePercentIdx; + float fps, minFps, maxFps; + char onePercent[8], pointOnePercent[8]; + + time = Sys_Microseconds() - clc.timedemo.timeDemoStart; + + if (time <= 0) { + return; + } + + // timeFrames gets incremented before we get here, but we never have a chance to measure the frametime + // since the playback ends, therefore scrap the last frame entirely as it never gets stored + numFrames = clc.timedemo.timeDemoFrames - 1; + + fps = numFrames * 1000000.0f / time; + + Com_Memcpy(sortedFrametimes, clc.timedemo.frametime, numFrames * sizeof(uint32_t)); + qsort(sortedFrametimes, numFrames, sizeof(uint32_t), CL_CompareFrametimes); + + minFps = 1000000.0f / sortedFrametimes[numFrames - 1]; + maxFps = 1000000.0f / sortedFrametimes[0]; + + // filter out potential 0ms anomalies for maxfps + if (sortedFrametimes[0] == 0) { + for (i = 0; i < numFrames; i++) { + if (sortedFrametimes[i] != 0) { + maxFps = 1000000.0f / sortedFrametimes[i]; + break; + } + } + } + + onePercentIdx = (int)(0.01f * numFrames); + + // make sure we have enough total frames to display 1% lows + if (onePercentIdx) { + Com_sprintf(onePercent, sizeof(onePercent), "%3.2f", 1000000.0f / sortedFrametimes[numFrames - 1 - onePercentIdx]); + } + + pointOnePercentIdx = (int)(0.001f * numFrames); + + // make sure we have enough total frames to display 0.1% lows + if (pointOnePercentIdx) { + Com_sprintf(pointOnePercent, sizeof(pointOnePercent), "%3.2f", 1000000.0f / sortedFrametimes[numFrames - 1 - pointOnePercentIdx]); + } + + Com_Printf("\n----- Benchmark results -----\n"); + Com_Printf("\n%-18s %3.2f sec\n%-18s %i\n%-18s %3.2f\n%-18s %3.2f\n%-18s %3.2f\n%-18s %s\n%-18s %s\n", + "Time elapsed:", time / 1000000.0f, + "Total frames:", numFrames, + "Minimum fps:", minFps, + "Maximum fps:", maxFps, + "Average fps:", fps, + "99th pct. min:", onePercentIdx ? onePercent : "--", + "99.9th pct. min:", pointOnePercentIdx ? pointOnePercent : "--"); + Com_Printf("\n-----------------------------\n\n"); +} + /* ================= CL_DemoCompleted @@ -757,13 +863,15 @@ CL_DemoCompleted */ static void CL_DemoCompleted( void ) { if ( com_timedemo->integer ) { - int time; + CL_TimedemoResults(); - time = Sys_Milliseconds() - clc.timeDemoStart; - if ( time > 0 ) { - Com_Printf( "%i frames, %3.*f seconds: %3.1f fps\n", clc.timeDemoFrames, - time > 10000 ? 1 : 2, time/1000.0, clc.timeDemoFrames*1000.0 / time ); + // reset timedemo cvar if 'benchmark' command forcibly enabled it + if (cls.benchmarking && cls.resetTimedemoCvar) { + Cvar_Set("timedemo", "0"); } + + cls.benchmarking = qfalse; + cls.resetTimedemoCvar = qfalse; } // fretn @@ -3316,6 +3424,11 @@ void CL_Frame( int msec, int realMsec ) { float fps; float frameDuration; aviRecordingState_t aviRecord = AVIDEMO_NONE; + int64_t frameStart = 0; + + if (clc.demoplaying && com_timedemo && com_timedemo->integer) { + frameStart = Sys_Microseconds(); + } CL_TrackCvarChanges( qfalse ); @@ -3468,6 +3581,12 @@ void CL_Frame( int msec, int realMsec ) { cls.discordInit = qfalse; } #endif + + if (clc.demoplaying && clc.timedemo.timeDemoFrames && com_timedemo && com_timedemo->integer) { + // use circular buffer to store frametimes, the array should hold enough frames for ~3h of demo playback, + // but in case of extremely long demos, just start dropping frames from the beginning + clc.timedemo.frametime[(clc.timedemo.timeDemoFrames - 1) % MAX_TIMEDEMO_FRAMES] = Sys_Microseconds() - frameStart; + } } @@ -4392,6 +4511,7 @@ static void CL_InitGLimp_Cvars( void ) static const cmdListItem_t cl_cmds[] = { { "addFavorite", CL_AddFavorite_f, NULL }, + { "benchmark", CL_StartBenchmark_f, CL_CompleteDemoName }, { "cache_endgather", CL_Cache_EndGather_f, NULL }, { "cache_mapchange", CL_Cache_MapChange_f, NULL }, { "cache_setindex", CL_Cache_SetIndex_f, NULL }, diff --git a/src/client/client.h b/src/client/client.h index 0bca8d86..9cf1ca6e 100644 --- a/src/client/client.h +++ b/src/client/client.h @@ -214,6 +214,14 @@ demo through a file. ============================================================================= */ +#define MAX_TIMEDEMO_FRAMES 262140 + +typedef struct { + uint32_t frametime[MAX_TIMEDEMO_FRAMES]; + int timeDemoFrames; // counter of rendered frames + int64_t timeDemoStart; // cls.realtime before first frame + int timeDemoBaseTime; // each frame will be at this time + frameNum * 50 +} timedemo_t ; typedef struct { @@ -290,9 +298,7 @@ typedef struct { fileHandle_t wavefile; int wavetime; - int timeDemoFrames; // counter of rendered frames - int timeDemoStart; // cls.realtime before first frame - int timeDemoBaseTime; // each frame will be at this time + frameNum * 50 + timedemo_t timedemo; float aviVideoFrameRemainder; float aviSoundFrameRemainder; @@ -432,6 +438,8 @@ typedef struct { float biasX; float biasY; + qboolean benchmarking; + qboolean resetTimedemoCvar; } clientStatic_t; extern int bigchar_width; From 0909e00419b02aceaf865c07884d5c1a5677ed11 Mon Sep 17 00:00:00 2001 From: Aciz Date: Sun, 11 Aug 2024 21:04:13 +0300 Subject: [PATCH 2/4] Add stability metric Percentage of frames that were at or above com_maxfps value --- src/client/cl_main.c | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/src/client/cl_main.c b/src/client/cl_main.c index 919ec55c..ea3bbd1c 100644 --- a/src/client/cl_main.c +++ b/src/client/cl_main.c @@ -801,6 +801,7 @@ static void CL_TimedemoResults(void) { int onePercentIdx, pointOnePercentIdx; float fps, minFps, maxFps; char onePercent[8], pointOnePercent[8]; + int desiredFrametime, numOptimalFrames; time = Sys_Microseconds() - clc.timedemo.timeDemoStart; @@ -844,15 +845,25 @@ static void CL_TimedemoResults(void) { Com_sprintf(pointOnePercent, sizeof(pointOnePercent), "%3.2f", 1000000.0f / sortedFrametimes[numFrames - 1 - pointOnePercentIdx]); } + desiredFrametime = 1000 / com_maxfps->integer; + numOptimalFrames = 0; + + for (i = 0; i < numFrames; i++) { + if (sortedFrametimes[i] / 1000.0f <= desiredFrametime) { + numOptimalFrames++; + } + } + Com_Printf("\n----- Benchmark results -----\n"); - Com_Printf("\n%-18s %3.2f sec\n%-18s %i\n%-18s %3.2f\n%-18s %3.2f\n%-18s %3.2f\n%-18s %s\n%-18s %s\n", + Com_Printf("\n%-18s %3.2f sec\n%-18s %i\n%-18s %3.2f\n%-18s %3.2f\n%-18s %3.2f\n%-18s %s\n%-18s %s\n%-18s %3.2f pct\n", "Time elapsed:", time / 1000000.0f, "Total frames:", numFrames, "Minimum fps:", minFps, "Maximum fps:", maxFps, "Average fps:", fps, "99th pct. min:", onePercentIdx ? onePercent : "--", - "99.9th pct. min:", pointOnePercentIdx ? pointOnePercent : "--"); + "99.9th pct. min:", pointOnePercentIdx ? pointOnePercent : "--", + "Stability:", (float)numOptimalFrames / (float)numFrames * 100.0f); Com_Printf("\n-----------------------------\n\n"); } From 095b0f2e6e12472446a03622330c263a235c05c2 Mon Sep 17 00:00:00 2001 From: Aciz Date: Sun, 11 Aug 2024 21:59:47 +0300 Subject: [PATCH 3/4] Const correctness --- src/client/cl_main.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/client/cl_main.c b/src/client/cl_main.c index ea3bbd1c..08be5a7a 100644 --- a/src/client/cl_main.c +++ b/src/client/cl_main.c @@ -777,8 +777,8 @@ CL_CompareFrametimes ================= */ static int CL_CompareFrametimes(const void *a, const void *b) { - const uint32_t arg1 = *(uint32_t *)a; - const uint32_t arg2 = *(uint32_t *)b; + const uint32_t arg1 = *(const uint32_t *)a; + const uint32_t arg2 = *(const uint32_t *)b; if (arg1 > arg2) { return 1; From f436f3266b216c04a8e3b1b1e5b2bf2c54b99ece Mon Sep 17 00:00:00 2001 From: Aciz Date: Sun, 11 Aug 2024 22:49:23 +0300 Subject: [PATCH 4/4] Optimize optimal frame calculation No need to iterate all frames, we can exit as soon as we hit a frametime that is higher than desired as we are iterating over the sorted array --- src/client/cl_main.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/client/cl_main.c b/src/client/cl_main.c index 08be5a7a..6666764d 100644 --- a/src/client/cl_main.c +++ b/src/client/cl_main.c @@ -849,9 +849,11 @@ static void CL_TimedemoResults(void) { numOptimalFrames = 0; for (i = 0; i < numFrames; i++) { - if (sortedFrametimes[i] / 1000.0f <= desiredFrametime) { - numOptimalFrames++; + if (sortedFrametimes[i] / 1000.0f > desiredFrametime) { + break; } + + numOptimalFrames++; } Com_Printf("\n----- Benchmark results -----\n");