From dd8307ef4c32362b50ca8591b6b5a476c9bed009 Mon Sep 17 00:00:00 2001 From: Aciz Date: Sun, 11 Aug 2024 16:42:12 +0300 Subject: [PATCH] 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;