diff --git a/polymer/eduke32/build/src/sdlayer.c b/polymer/eduke32/build/src/sdlayer.c index dc6ce9f3f..6dc89b387 100644 --- a/polymer/eduke32/build/src/sdlayer.c +++ b/polymer/eduke32/build/src/sdlayer.c @@ -825,7 +825,6 @@ void sampletimer(void) int32_t n; if (!timerfreq) return; - i = SDL_GetTicks(); n = (int32_t)(i * timerticspersec / timerfreq) - timerlastsample; if (n>0) diff --git a/polymer/eduke32/source/demo.c b/polymer/eduke32/source/demo.c index 58f346d1a..e79cb9656 100644 --- a/polymer/eduke32/source/demo.c +++ b/polymer/eduke32/source/demo.c @@ -227,10 +227,13 @@ error_wopen_demo: g_demo_cnt = 1; } -static int32_t g_demo_playFirstFlag = 0; -void Demo_PlayFirst(void) +// demo_profile: < 0: prepare +static int32_t g_demo_playFirstFlag, g_demo_profile, g_demo_stopProfile; +void Demo_PlayFirst(int32_t prof) { g_demo_playFirstFlag = 1; + Bassert(prof >= 0); + g_demo_profile = -prof; // prepare } @@ -355,6 +358,106 @@ static int32_t Demo_ReadSync(int32_t errcode) return 0; } +////////// DEMO PROFILING (TIMEDEMO MODE) ////////// +static struct { + int32_t numtics, numframes; + double totalgamems; + double totalroomsdrawms, totalrestdrawms; + double starthitickms; +} g_prof; + +int32_t Demo_IsProfiling(void) +{ + return (g_demo_profile > 0); +} + +void Demo_StopProfiling(void) +{ + g_demo_stopProfile = 1; +} + +static void Demo_GToc(double t) +{ + g_prof.numtics++; + g_prof.totalgamems += gethitickms()-t; +} + +static void Demo_RToc(double t1, double t2) +{ + g_prof.numframes++; + g_prof.totalroomsdrawms += t2-t1; + g_prof.totalrestdrawms += gethitickms()-t2; +} + +static void Demo_DisplayProfStatus(void) +{ + char buf[64]; + + static int32_t lastpercent=-1; + int32_t percent = (100*g_demo_cnt)/g_demo_totalCnt; + + if (lastpercent == percent) + return; + lastpercent = percent; + + clearallviews(0); + Bsnprintf(buf, sizeof(buf), "timing... %d/%d game tics (%d %%)", + g_demo_cnt, g_demo_totalCnt, percent); + gametext(160,60, buf, 0, 2+8+16); + nextpage(); +} + +static void Demo_SetupProfile(void) +{ + g_demo_profile *= -1; // now >0: profile for real + + g_demo_soundToggle = ud.config.SoundToggle; + ud.config.SoundToggle = 0; // restored by Demo_FinishProfile() + + Bmemset(&g_prof, 0, sizeof(g_prof)); + + g_prof.starthitickms = gethitickms(); +} + +static void Demo_FinishProfile(void) +{ + if (Demo_IsProfiling()) + { + int32_t dn=g_whichDemo-1; + int32_t nt=g_prof.numtics, nf=g_prof.numframes; + double gms=g_prof.totalgamems; + double dms1=g_prof.totalroomsdrawms, dms2=g_prof.totalrestdrawms; + + ud.config.SoundToggle = g_demo_soundToggle; + + if (nt > 0) + { + OSD_Printf("== demo %d: %d gametics\n", dn, nt); + OSD_Printf("== demo %d game times: %.03f ms (%.03f us/gametic)\n", + dn, gms, (gms*1000.0)/nt); + } + + if (nf > 0) + { + OSD_Printf("== demo %d: %d frames (%d frames/gametic)\n", dn, nf, g_demo_profile-1); + OSD_Printf("== demo %d drawrooms times: %.03f s (%.03f ms/frame)\n", + dn, dms1/1000.0, dms1/nf); + OSD_Printf("== demo %d drawrest times: %.03f s (%.03f ms/frame)\n", + dn, dms2/1000.0, dms2/nf); + } + + { + double totalprofms = gms+dms1+dms2; + double totalms = gethitickms()-g_prof.starthitickms; + OSD_Printf("== demo %d: non-profiled time overhead: %.02f %%\n", + dn, 100.0*totalms/totalprofms - 100.0); + } + } + + g_demo_profile = 0; + g_demo_stopProfile = 0; +} +//////////////////// int32_t G_PlaybackDemo(void) { @@ -366,6 +469,8 @@ int32_t G_PlaybackDemo(void) if (ready2send) return 0; + g_demo_profile = 0; + RECHECK: #if KRANDDEBUG @@ -421,6 +526,10 @@ RECHECK: #if KRANDDEBUG krd_enable(2); #endif + if (g_demo_profile < 0) + { + Demo_SetupProfile(); + } } if (foundemo == 0 || in_menu || I_CheckAllInput() || numplayers > 1) @@ -447,6 +556,7 @@ RECHECK: { g_demo_playFirstFlag = 0; g_whichDemo = 1; // force g_firstDemoFile[] + g_demo_paused = 0; goto nextdemo_nomenu; } @@ -493,6 +603,9 @@ RECHECK: Demo_RestoreModes(menu); } + if (g_demo_stopProfile) + Demo_FinishProfile(); + while (totalclock >= (lockclock+TICSPERFRAME) // || (ud.reccnt > REALGAMETICSPERSEC*2 && ud.pause_on) || (g_demo_goalCnt>0 && g_demo_cnt=g_demo_goalCnt-g_demo_cnt) + { G_DoMoveThings(); // increases lockclock by TICSPERFRAME + } else + { lockclock += TICSPERFRAME; + } } else { @@ -631,6 +756,9 @@ nextdemo_nomenu: totalclock = lockclock; } + if (Demo_IsProfiling()) + totalclock += TICSPERFRAME; + if (foundemo == 0) { G_DrawBackground(); @@ -640,6 +768,9 @@ nextdemo_nomenu: static uint32_t nextrender = 0, framewaiting = 0; uint32_t tt; + // NOTE: currently, no key/mouse events will be seen while + // demo-profiling because we need 'totalclock' for ourselves. + // And handleevents() -> sampletimer() would mess that up. G_HandleLocalKeys(); if (framewaiting) @@ -657,7 +788,41 @@ nextdemo_nomenu: tt = getticks(); - if (r_maxfps == 0 || tt >= nextrender) + // Render one frame (potentially many if profiling) + if (Demo_IsProfiling()) + { + int32_t i, num = g_demo_profile-1; + + Bassert(totalclock-ototalclock==4); + + for (i=0; i>16); + + G_DrawRooms(screenpeek,j); + + t2 = gethitickms(); + + G_DisplayRest(j); + + Demo_RToc(t1, t2); + } + + totalclock = ototalclock+4; + + // draw status + Demo_DisplayProfStatus(); + } + else if (r_maxfps == 0 || tt >= nextrender) { if (tt > nextrender+g_frameDelay) nextrender = tt; @@ -674,7 +839,7 @@ nextdemo_nomenu: framewaiting++; } - if ((g_player[myconnectindex].ps->gm&MODE_MENU) == 0) + if (!Demo_IsProfiling() && (g_player[myconnectindex].ps->gm&MODE_MENU) == 0) { if (demoplay_showsync && outofsync) gametext(160,100,"OUT OF SYNC",0,2+8+16); @@ -717,7 +882,10 @@ nextdemo_nomenu: } if ((g_player[myconnectindex].ps->gm&MODE_MENU) && (g_player[myconnectindex].ps->gm&MODE_EOL)) + { + Demo_FinishProfile(); goto RECHECK; + } if (I_EscapeTrigger() && (g_player[myconnectindex].ps->gm&MODE_MENU) == 0 && (g_player[myconnectindex].ps->gm&MODE_TYPE) == 0) { @@ -729,7 +897,12 @@ nextdemo_nomenu: S_MenuSound(); } - if (g_player[myconnectindex].ps->gm&MODE_TYPE) + if (Demo_IsProfiling()) + { + // Do nothing: sampletimer() is reached from M_DisplayMenus() -> + // Net_GetPackets() else. + } + else if (g_player[myconnectindex].ps->gm&MODE_TYPE) { Net_EnterMessage(); @@ -756,7 +929,8 @@ nextdemo_nomenu: } } - G_PrintGameQuotes(screenpeek); + if (!Demo_IsProfiling()) + G_PrintGameQuotes(screenpeek); if (ud.last_camsprite != ud.camerasprite) { @@ -770,7 +944,10 @@ nextdemo_nomenu: rotatesprite_fs((320-50)<<16,9<<16,65536L,0,BETAVERSION,0,0,2+8+16+128); } - G_HandleAsync(); + // NOTE: We must prevent handleevents() and Net_GetPackets() from + // updating totalclock when profiling (both via sampletimer()): + if (!Demo_IsProfiling()) + G_HandleAsync(); if (ud.recstat==0) nextpage(); @@ -794,6 +971,8 @@ nextdemo_nomenu: ud.multimode = numplayers; // fixes 2 infinite loops after watching demo kclose(g_demo_recFilePtr); g_demo_recFilePtr = -1; + Demo_FinishProfile(); + // if we're in the menu, try next demo immediately if (g_player[myconnectindex].ps->gm&MODE_MENU) goto RECHECK; diff --git a/polymer/eduke32/source/demo.h b/polymer/eduke32/source/demo.h index 9ac77bd3e..fead43a26 100644 --- a/polymer/eduke32/source/demo.h +++ b/polymer/eduke32/source/demo.h @@ -48,7 +48,10 @@ void G_CloseDemoWrite(void); void G_DemoRecord(void); void G_OpenDemoWrite(void); -void Demo_PlayFirst(void); +void Demo_PlayFirst(int32_t prof); + +int32_t Demo_IsProfiling(void); +void Demo_StopProfiling(void); #if KRANDDEBUG int32_t krd_print(const char *filename); diff --git a/polymer/eduke32/source/game.c b/polymer/eduke32/source/game.c index 56ec058b5..ec7b5542b 100644 --- a/polymer/eduke32/source/game.c +++ b/polymer/eduke32/source/game.c @@ -3021,10 +3021,13 @@ void G_DisplayRest(int32_t smoothratio) rotatesprite_fs((320-50)<<16,9<<16,65536L,0,BETAVERSION,0,0,2+8+16+128); } - if (g_player[myconnectindex].ps->gm&MODE_TYPE) - Net_EnterMessage(); - else - M_DisplayMenus(); + if (!Demo_IsProfiling()) + { + if (g_player[myconnectindex].ps->gm&MODE_TYPE) + Net_EnterMessage(); + else + M_DisplayMenus(); + } { static int32_t applied = 0; diff --git a/polymer/eduke32/source/osdcmds.c b/polymer/eduke32/source/osdcmds.c index 4e8ba2a80..0935cfbed 100644 --- a/polymer/eduke32/source/osdcmds.c +++ b/polymer/eduke32/source/osdcmds.c @@ -287,6 +287,22 @@ static int32_t osdcmd_map(const osdfuncparm_t *parm) return OSDCMD_OK; } +// demo [] +// +// To profile a demo ("timedemo mode"), can be given in the range 0-8, +// which will start to replay it as fast as possible, rendering frames +// for each gametic. +// +// Notes: +// * The demos should be recorded with demorec_diffs set to 0, so that the +// game state updates are actually computed. +// * There's currently no way to abort the profiling. +// * With greater than 1, interpolation should be calculated properly, +// though this has not been verified by looking at the frames. +// * When testing whether a change in the source has an effect on performance, +// the variance of the run times MUST be taken into account (that is, the +// replaying must be performed multiple times for the old and new versions, +// etc.) static int32_t osdcmd_demo(const osdfuncparm_t *parm) { if (numplayers > 1) @@ -301,20 +317,21 @@ static int32_t osdcmd_demo(const osdfuncparm_t *parm) return OSDCMD_OK; } - if (parm->numparms != 1) + if (parm->numparms != 1 && parm->numparms != 2) return OSDCMD_SHOWHELP; { char *tailptr; const char *demostr = parm->parms[0]; int32_t i = Bstrtol(demostr, &tailptr, 10); + int32_t prof = parm->numparms==2 ? Batoi(parm->parms[1]) : -1; if (tailptr!=demostr && i>=0 && i<=999) // demo number passed Bsprintf(g_firstDemoFile, "edemo%03d.edm", i); else // demo file name passed maybe_append_ext(g_firstDemoFile, sizeof(g_firstDemoFile), parm->parms[0], ".edm"); - Demo_PlayFirst(); + Demo_PlayFirst(clamp(prof, -1, 8)+1); } return OSDCMD_OK;