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

diff --git a/pr_comp.h b/pr_comp.h
index 8ccdaf6d74ace96f3ca9a6909ebbb1a6692942c1..eab88b50020f9b147b0ca35bee2d773a8210e74d 100644 (file)
--- 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 ff2c3bbff38df24b8fcbfc54b0148887b4ea986c..c6fc665370624af69c878c164b83b97a80494568 100644 (file)
--- 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 fd6b1d0318faa4fddbb818925f897dd6a63bc2e9..e3bb497feab3374875a697109fb16147aa091db7 100644 (file)
--- 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 a889f66b1f7b1b01d256d7678b74623605d67786..80287cab1ae37ea8054bf2f573df5409fcfc38de 100644 (file)
--- 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 ; i<prog->progs->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 <program name>\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();
 }