From 2a28f051d86861fb4656d3a46c40bf2a736b21e5 Mon Sep 17 00:00:00 2001 From: divverent Date: Fri, 19 Oct 2007 10:51:33 +0000 Subject: [PATCH] prvm_callprofile: a flat profile, time based, including subcalls git-svn-id: svn://svn.icculus.org/twilight/trunk/darkplaces@7647 d7cf8633-e32d-0410-b094-e92efae38249 --- pr_comp.h | 1 + progsvm.h | 2 ++ prvm_edict.c | 3 +++ prvm_exec.c | 65 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 71 insertions(+) diff --git a/pr_comp.h b/pr_comp.h index 8ccdaf6d..eab88b50 100644 --- a/pr_comp.h +++ b/pr_comp.h @@ -167,6 +167,7 @@ typedef struct mfunction_s double profile; // runtime double builtinsprofile; // cost of builtin functions called by this function double callcount; // times the functions has been called since the last profile call + double totaltime; // total execution time of this function DIRECTLY FROM THE ENGINE int s_name; int s_file; // source file defined in diff --git a/progsvm.h b/progsvm.h index ff2c3bbf..c6fc6653 100644 --- a/progsvm.h +++ b/progsvm.h @@ -288,6 +288,7 @@ prvm_prog_funcoffsets_t; // NOTE: external code has to create and free the mempools but everything else is done by prvm ! typedef struct prvm_prog_s { + double starttime; dprograms_t *progs; mfunction_t *functions; char *strings; @@ -464,6 +465,7 @@ void _PRVM_FreeAll (const char *filename, int fileline); void PRVM_Profile (int maxfunctions, int mininstructions); void PRVM_Profile_f (void); +void PRVM_CallProfile_f (void); void PRVM_PrintFunction_f (void); void PRVM_PrintState(void); diff --git a/prvm_edict.c b/prvm_edict.c index fd6b1d03..e3bb497f 100644 --- a/prvm_edict.c +++ b/prvm_edict.c @@ -1500,6 +1500,7 @@ void PRVM_ResetProg() PRVM_GCALL(reset_cmd)(); Mem_FreePool(&prog->progs_mempool); memset(prog,0,sizeof(prvm_prog_t)); + prog->starttime = Sys_DoubleTime(); } /* @@ -2028,6 +2029,7 @@ void PRVM_Init (void) Cmd_AddCommand ("prvm_edicts", PRVM_ED_PrintEdicts_f, "prints all data about all entities in the selected VM (server, client, menu)"); Cmd_AddCommand ("prvm_edictcount", PRVM_ED_Count_f, "prints number of active entities in the selected VM (server, client, menu)"); Cmd_AddCommand ("prvm_profile", PRVM_Profile_f, "prints execution statistics about the most used QuakeC functions in the selected VM (server, client, menu)"); + Cmd_AddCommand ("prvm_callprofile", PRVM_CallProfile_f, "prints execution statistics about the most time consuming QuakeC calls from the engine in the selected VM (server, client, menu)"); Cmd_AddCommand ("prvm_fields", PRVM_Fields_f, "prints usage statistics on properties (how many entities have non-zero values) in the selected VM (server, client, menu)"); Cmd_AddCommand ("prvm_globals", PRVM_Globals_f, "prints all global variables in the selected VM (server, client, menu)"); Cmd_AddCommand ("prvm_global", PRVM_Global_f, "prints value of a specified global variable in the selected VM (server, client, menu)"); @@ -2061,6 +2063,7 @@ void PRVM_InitProg(int prognr) PRVM_ResetProg(); memset(prog, 0, sizeof(prvm_prog_t)); + prog->starttime = Sys_DoubleTime(); prog->error_cmd = Host_Error; } diff --git a/prvm_exec.c b/prvm_exec.c index a889f66b..80287cab 100644 --- a/prvm_exec.c +++ b/prvm_exec.c @@ -266,6 +266,43 @@ void PRVM_StackTrace (void) } +void PRVM_CallProfile () +{ + mfunction_t *f, *best; + int i; + double max; + double sum; + + Con_Printf( "%s Call Profile:\n", PRVM_NAME ); + + sum = 0; + do + { + max = 0; + best = NULL; + for (i=0 ; iprogs->numfunctions ; i++) + { + f = &prog->functions[i]; + if (max < f->totaltime) + { + max = f->totaltime; + best = f; + } + } + if (best) + { + sum += best->totaltime; + Con_Printf("%9.4f %s\n", best->totaltime, PRVM_GetString(best->s_name)); + best->totaltime = 0; + } + } while (best); + + Con_Printf("Total time since last profile reset: %9.4f\n", Sys_DoubleTime() - prog->starttime); + Con_Printf(" - used by QC code of this VM: %9.4f\n", sum); + + prog->starttime = Sys_DoubleTime(); +} + void PRVM_Profile (int maxfunctions, int mininstructions) { mfunction_t *f, *best; @@ -305,6 +342,29 @@ void PRVM_Profile (int maxfunctions, int mininstructions) } while (best); } +/* +============ +PRVM_CallProfile_f + +============ +*/ +void PRVM_CallProfile_f (void) +{ + if (Cmd_Argc() != 2) + { + Con_Print("prvm_callprofile \n"); + return; + } + + PRVM_Begin; + if(!PRVM_SetProgFromString(Cmd_Argv(1))) + return; + + PRVM_CallProfile(); + + PRVM_End; +} + /* ============ PRVM_Profile_f @@ -497,6 +557,9 @@ void PRVM_ExecuteProgram (func_t fnum, const char *errormessage) prvm_eval_t *ptr; int jumpcount, cachedpr_trace, exitdepth; int restorevm_tempstringsbuf_cursize; + double calltime; + + calltime = Sys_DoubleTime(); if (!fnum || fnum >= (unsigned int)prog->progs->numfunctions) { @@ -599,5 +662,7 @@ cleanup: // delete tempstrings created by this function vm_tempstringsbuf.cursize = restorevm_tempstringsbuf_cursize; + prog->functions[fnum].totaltime += (Sys_DoubleTime() - calltime); + SV_FlushBroadcastMessages(); } -- 2.39.2