From 25dc9d61580862bae4ee23c4ebb93fdec06ac55d Mon Sep 17 00:00:00 2001 From: divverent Date: Thu, 17 Sep 2009 09:43:47 +0000 Subject: [PATCH] make profile output more verbous (including time of child functions) add new command prvm_childprofile to instead sort by the total time (including children) git-svn-id: svn://svn.icculus.org/twilight/trunk/darkplaces@9205 d7cf8633-e32d-0410-b094-e92efae38249 --- pr_comp.h | 3 ++ progsvm.h | 5 ++- prvm_edict.c | 1 + prvm_exec.c | 76 +++++++++++++++++++++++++++++++++++++++++----- prvm_execprogram.h | 6 ++-- 5 files changed, 79 insertions(+), 12 deletions(-) diff --git a/pr_comp.h b/pr_comp.h index eab88b50..45cc9f13 100644 --- a/pr_comp.h +++ b/pr_comp.h @@ -168,6 +168,9 @@ typedef struct mfunction_s 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 + double profile_total; // runtime + double builtinsprofile_total; // cost of builtin functions called by this function + int recursion; int s_name; int s_file; // source file defined in diff --git a/progsvm.h b/progsvm.h index d31f8eec..93b45059 100644 --- a/progsvm.h +++ b/progsvm.h @@ -40,6 +40,8 @@ typedef struct prvm_stack_s { int s; mfunction_t *f; + double profile_acc; + double builtinsprofile_acc; } prvm_stack_t; @@ -518,8 +520,9 @@ void *_PRVM_Alloc (size_t buffersize, const char *filename, int fileline); void _PRVM_Free (void *buffer, const char *filename, int fileline); void _PRVM_FreeAll (const char *filename, int fileline); -void PRVM_Profile (int maxfunctions, int mininstructions); +void PRVM_Profile (int maxfunctions, int mininstructions, int sortby); void PRVM_Profile_f (void); +void PRVM_ChildProfile_f (void); void PRVM_CallProfile_f (void); void PRVM_PrintFunction_f (void); diff --git a/prvm_edict.c b/prvm_edict.c index dcda2ed6..50ee3dbf 100644 --- a/prvm_edict.c +++ b/prvm_edict.c @@ -2189,6 +2189,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_childprofile", PRVM_ChildProfile_f, "prints execution statistics about the most used QuakeC functions in the selected VM (server, client, menu), sorted by time taken in function with child calls"); 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)"); diff --git a/prvm_exec.c b/prvm_exec.c index af50433f..b6c8a0ac 100644 --- a/prvm_exec.c +++ b/prvm_exec.c @@ -334,13 +334,14 @@ void PRVM_CallProfile (void) prog->starttime = Sys_DoubleTime(); } -void PRVM_Profile (int maxfunctions, int mininstructions) +void PRVM_Profile (int maxfunctions, int mininstructions, int sortby) { mfunction_t *f, *best; int i, num; double max; - Con_Printf( "%s Profile:\n[CallCount] [Statements] [BuiltinCost]\n", PRVM_NAME ); + Con_Printf( "%s Profile:\n[CallCount] [Statement] [BuiltinCt] [StmtTotal] [BltnTotal] [self]\n", PRVM_NAME ); + // 12345678901 12345678901 12345678901 12345678901 12345678901 123.45% num = 0; do @@ -350,10 +351,21 @@ void PRVM_Profile (int maxfunctions, int mininstructions) for (i=0 ; iprogs->numfunctions ; i++) { f = &prog->functions[i]; - if (max < f->profile + f->builtinsprofile + f->callcount) + if(sortby) { - max = f->profile + f->builtinsprofile + f->callcount; - best = f; + if (max < f->profile_total + f->builtinsprofile_total + f->callcount) + { + max = f->profile_total + f->builtinsprofile_total + f->callcount; + best = f; + } + } + else + { + if (max < f->profile + f->builtinsprofile + f->callcount) + { + max = f->profile + f->builtinsprofile + f->callcount; + best = f; + } } } if (best) @@ -361,13 +373,16 @@ void PRVM_Profile (int maxfunctions, int mininstructions) if (num < maxfunctions && max >= mininstructions) { if (best->first_statement < 0) - Con_Printf("%9.0f ----- builtin ----- %s\n", best->callcount, PRVM_GetString(best->s_name)); + Con_Printf("%11.0f ----------------------- builtin ----------------------- %s\n", best->callcount, PRVM_GetString(best->s_name)); + // 12345678901 12345678901 12345678901 12345678901 123.45% else - Con_Printf("%9.0f %9.0f %9.0f %s\n", best->callcount, best->profile, best->builtinsprofile, PRVM_GetString(best->s_name)); + Con_Printf("%11.0f %11.0f %11.0f %11.0f %11.0f %6.2f%% %s\n", best->callcount, best->profile, best->builtinsprofile, best->profile_total, best->builtinsprofile_total, (best->profile + best->builtinsprofile) * 100.0 / (best->profile_total + best->builtinsprofile_total), PRVM_GetString(best->s_name)); } num++; best->profile = 0; best->builtinsprofile = 0; + best->profile_total = 0; + best->builtinsprofile_total = 0; best->callcount = 0; } } while (best); @@ -419,7 +434,29 @@ void PRVM_Profile_f (void) if(!PRVM_SetProgFromString(Cmd_Argv(1))) return; - PRVM_Profile(howmany, 1); + PRVM_Profile(howmany, 1, 0); + + PRVM_End; +} + +void PRVM_ChildProfile_f (void) +{ + int howmany; + + howmany = 1<<30; + if (Cmd_Argc() == 3) + howmany = atoi(Cmd_Argv(2)); + else if (Cmd_Argc() != 2) + { + Con_Print("prvm_childprofile \n"); + return; + } + + PRVM_Begin; + if(!PRVM_SetProgFromString(Cmd_Argv(1))) + return; + + PRVM_Profile(howmany, 1, 1); PRVM_End; } @@ -515,6 +552,8 @@ int PRVM_EnterFunction (mfunction_t *f) prog->stack[prog->depth].s = prog->xstatement; prog->stack[prog->depth].f = prog->xfunction; + prog->stack[prog->depth].profile_acc = -f->profile; + prog->stack[prog->depth].builtinsprofile_acc = -f->builtinsprofile; prog->depth++; if (prog->depth >=PRVM_MAX_STACK_DEPTH) PRVM_ERROR ("stack overflow"); @@ -539,6 +578,7 @@ int PRVM_EnterFunction (mfunction_t *f) } } + ++f->recursion; prog->xfunction = f; return f->first_statement - 1; // offset the s++ } @@ -551,6 +591,7 @@ PRVM_LeaveFunction int PRVM_LeaveFunction (void) { int i, c; + mfunction_t *f; if (prog->depth <= 0) PRVM_ERROR ("prog stack underflow in %s", PRVM_NAME); @@ -568,7 +609,26 @@ int PRVM_LeaveFunction (void) // up stack prog->depth--; + f = prog->xfunction; + --f->recursion; prog->xfunction = prog->stack[prog->depth].f; + prog->stack[prog->depth].profile_acc += f->profile; + prog->stack[prog->depth].builtinsprofile_acc += f->builtinsprofile; + if(prog->depth > 0) + { + prog->stack[prog->depth-1].profile_acc += prog->stack[prog->depth].profile_acc; + prog->stack[prog->depth-1].builtinsprofile_acc += prog->stack[prog->depth].builtinsprofile_acc; + } + if(!f->recursion) + { + // if f is already on the call stack... + // we cannot add this profile data to it now + // or we would add it more than once + // so, let's only add to the function's profile if it is the outermost call + f->profile_total += prog->stack[prog->depth].profile_acc; + f->builtinsprofile_total += prog->stack[prog->depth].builtinsprofile_acc; + } + return prog->stack[prog->depth].s; } diff --git a/prvm_execprogram.h b/prvm_execprogram.h index 52da1343..3f597763 100644 --- a/prvm_execprogram.h +++ b/prvm_execprogram.h @@ -272,7 +272,7 @@ if (++jumpcount == 10000000) { prog->xstatement = st - prog->statements; - PRVM_Profile(1<<30, 1000000); + PRVM_Profile(1<<30, 1000000, 0); PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount); } #endif @@ -293,7 +293,7 @@ if (++jumpcount == 10000000) { prog->xstatement = st - prog->statements; - PRVM_Profile(1<<30, 1000000); + PRVM_Profile(1<<30, 1000000, 0); PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount); } #endif @@ -309,7 +309,7 @@ if (++jumpcount == 10000000) { prog->xstatement = st - prog->statements; - PRVM_Profile(1<<30, 1000000); + PRVM_Profile(1<<30, 1000000, 0); PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount); } #endif -- 2.39.2