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

diff --git a/pr_comp.h b/pr_comp.h
index eab88b50020f9b147b0ca35bee2d773a8210e74d..45cc9f13b538254245620e93a4454c917e41edd4 100644 (file)
--- 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  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
 
        int             s_name;
        int             s_file;                 // source file defined in

diff --git a/progsvm.h b/progsvm.h
index d31f8eeca64ec134e8616307e0e4792bff6235d3..93b450591083b13a76459f02392ba968680c3469 100644 (file)
--- a/progsvm.h
+++ b/progsvm.h
@@ -40,6 +40,8 @@ typedef struct prvm_stack_s
 {
        int                             s;
        mfunction_t             *f;
 {
        int                             s;
        mfunction_t             *f;

+       double                  profile_acc;
+       double                  builtinsprofile_acc;

 } prvm_stack_t;
 
 
 } 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_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_Profile_f (void);

+void PRVM_ChildProfile_f (void);

 void PRVM_CallProfile_f (void);
 void PRVM_PrintFunction_f (void);
 
 void PRVM_CallProfile_f (void);
 void PRVM_PrintFunction_f (void);
 

diff --git a/prvm_edict.c b/prvm_edict.c
index dcda2ed67a747860b7b9d455175dea35d61cf2bc..50ee3dbff1d508712cdafdd93d0dc058329421b4 100644 (file)
--- 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_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)");
        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 af50433f66c17ab2baf658110a3bf37cd9606b3b..b6c8a0acf70081cc23a61fec4d8899ebcaf5e936 100644 (file)
--- a/prvm_exec.c
+++ b/prvm_exec.c
@@ -334,13 +334,14 @@ void PRVM_CallProfile (void)
        prog->starttime = Sys_DoubleTime();
 }
 
        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;
 
 {
        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
 
        num = 0;
        do


@@ -350,10 +351,21 @@ void PRVM_Profile (int maxfunctions, int mininstructions)
                for (i=0 ; i<prog->progs->numfunctions ; i++)
                {
                        f = &prog->functions[i];
                for (i=0 ; i<prog->progs->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)
                        }
                }
                if (best)


@@ -361,13 +373,16 @@ void PRVM_Profile (int maxfunctions, int mininstructions)
                        if (num < maxfunctions && max >= mininstructions)
                        {
                                if (best->first_statement < 0)
                        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
                                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;
                        }
                        num++;
                        best->profile = 0;
                        best->builtinsprofile = 0;

+                       best->profile_total = 0;
+                       best->builtinsprofile_total = 0;

                        best->callcount = 0;
                }
        } while (best);
                        best->callcount = 0;
                }
        } while (best);


@@ -419,7 +434,29 @@ void PRVM_Profile_f (void)
        if(!PRVM_SetProgFromString(Cmd_Argv(1)))
                return;
 
        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 <program name>\n");
+               return;
+       }
+
+       PRVM_Begin;
+       if(!PRVM_SetProgFromString(Cmd_Argv(1)))
+               return;
+
+       PRVM_Profile(howmany, 1, 1);

 
        PRVM_End;
 }
 
        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].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");
        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++
 }
        prog->xfunction = f;
        return f->first_statement - 1;  // offset the s++
 }


@@ -551,6 +591,7 @@ PRVM_LeaveFunction
 int PRVM_LeaveFunction (void)
 {
        int             i, c;
 int PRVM_LeaveFunction (void)
 {
        int             i, c;

+       mfunction_t *f;

 
        if (prog->depth <= 0)
                PRVM_ERROR ("prog stack underflow in %s", PRVM_NAME);
 
        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--;
 
 // up stack
        prog->depth--;

+       f = prog->xfunction;
+       --f->recursion;

        prog->xfunction = prog->stack[prog->depth].f;
        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;
 }
 
        return prog->stack[prog->depth].s;
 }
 

diff --git a/prvm_execprogram.h b/prvm_execprogram.h
index 52da1343afc1f36a3a446c4824da653aef4b9c7f..3f597763224dcf350bf478658de136eb554530a6 100644 (file)
--- a/prvm_execprogram.h
+++ b/prvm_execprogram.h
@@ -272,7 +272,7 @@
                                        if (++jumpcount == 10000000)
                                        {
                                                prog->xstatement = st - prog->statements;
                                        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
                                                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;
                                        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
                                                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;
                                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
                                        PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount);
                                }
 #endif