int locals; // total ints of parms + locals
// these are doubles so that they can count up to 54bits or so rather than 32bit
+ double tprofile; // realtime in this function
+ double tbprofile; // realtime in builtins called by this function (NOTE: builtins also have a tprofile!)
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
+ double tprofile_total; // runtime (NOTE: tbprofile_total makes no real sense, so not accumulating that)
double profile_total; // runtime
double builtinsprofile_total; // cost of builtin functions called by this function
int recursion;
{
int s;
mfunction_t *f;
+ double tprofile_acc;
double profile_acc;
double builtinsprofile_acc;
} prvm_stack_t;
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, int sortby);
+void PRVM_Profile (int maxfunctions, double mintime, int sortby);
void PRVM_Profile_f (void);
void PRVM_ChildProfile_f (void);
void PRVM_CallProfile_f (void);
cvar_t prvm_traceqc = {0, "prvm_traceqc", "0", "prints every QuakeC statement as it is executed (only for really thorough debugging!)"};
// LordHavoc: counts usage of each QuakeC statement
cvar_t prvm_statementprofiling = {0, "prvm_statementprofiling", "0", "counts how many times each QuakeC statement has been executed, these counts are displayed in prvm_printfunction output (if enabled)"};
+cvar_t prvm_timeprofiling = {0, "prvm_timeprofiling", "0", "counts how long each function has been executed, these counts are displayed in prvm_profile output (if enabled)"};
cvar_t prvm_backtraceforwarnings = {0, "prvm_backtraceforwarnings", "0", "print a backtrace for warnings too"};
cvar_t prvm_leaktest = {0, "prvm_leaktest", "0", "try to detect memory leaks in strings or entities"};
cvar_t prvm_leaktest_ignore_classnames = {0, "prvm_leaktest_ignore_classnames", "", "classnames of entities to NOT leak check because they are found by find(world, classname, ...) but are actually spawned by QC code (NOT map entities)"};
Cvar_RegisterVariable (&prvm_language);
Cvar_RegisterVariable (&prvm_traceqc);
Cvar_RegisterVariable (&prvm_statementprofiling);
+ Cvar_RegisterVariable (&prvm_timeprofiling);
Cvar_RegisterVariable (&prvm_backtraceforwarnings);
Cvar_RegisterVariable (&prvm_leaktest);
Cvar_RegisterVariable (&prvm_leaktest_ignore_classnames);
=================
*/
extern cvar_t prvm_statementprofiling;
+extern cvar_t prvm_timeprofiling;
void PRVM_PrintStatement (dstatement_t *s)
{
size_t i;
prog->starttime = Sys_DoubleTime();
}
-void PRVM_Profile (int maxfunctions, int mininstructions, int sortby)
+void PRVM_Profile (int maxfunctions, double mintime, int sortby)
{
mfunction_t *f, *best;
int i, num;
double max;
- Con_Printf( "%s Profile:\n[CallCount] [Statement] [BuiltinCt] [StmtTotal] [BltnTotal] [self]\n", PRVM_NAME );
- // 12345678901 12345678901 12345678901 12345678901 12345678901 123.45%
+ if(!prvm_timeprofiling.integer)
+ mintime *= 10000000; // count each statement as about 0.1µs
+
+ if(prvm_timeprofiling.integer)
+ Con_Printf( "%s Profile:\n[CallCount] [Time] [BuiltinTm] [Statement] [BuiltinCt] [TimeTotal] [StmtTotal] [BltnTotal] [self]\n", PRVM_NAME );
+ // 12345678901 12345678901 12345678901 12345678901 12345678901 12345678901 12345678901 123.45%
+ else
+ Con_Printf( "%s Profile:\n[CallCount] [Statement] [BuiltinCt] [StmtTotal] [BltnTotal] [self]\n", PRVM_NAME );
+ // 12345678901 12345678901 12345678901 12345678901 12345678901 123.45%
num = 0;
do
for (i=0 ; i<prog->progs->numfunctions ; i++)
{
f = &prog->functions[i];
- if(sortby)
+ if(prvm_timeprofiling.integer)
{
- if (max < f->profile_total + f->builtinsprofile_total + f->callcount)
+ if(sortby)
{
- max = f->profile_total + f->builtinsprofile_total + f->callcount;
- best = f;
+ if(f->first_statement < 0)
+ {
+ if (max < f->tprofile)
+ {
+ max = f->tprofile;
+ best = f;
+ }
+ }
+ else
+ {
+ if (max < f->tprofile_total)
+ {
+ max = f->tprofile_total;
+ best = f;
+ }
+ }
+ }
+ else
+ {
+ if (max < f->tprofile + f->tbprofile)
+ {
+ max = f->tprofile + f->tbprofile;
+ best = f;
+ }
}
}
else
{
- 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 (num < maxfunctions && max >= mininstructions)
+ if (num < maxfunctions && max > mintime)
{
- if (best->first_statement < 0)
- Con_Printf("%11.0f ----------------------- builtin ----------------------- %s\n", best->callcount, PRVM_GetString(best->s_name));
- // 12345678901 12345678901 12345678901 12345678901 123.45%
+ if(prvm_timeprofiling.integer)
+ {
+ if (best->first_statement < 0)
+ Con_Printf("%11.0f %11.6f ------------- builtin ------------- %11.6f ----------- builtin ----------- %s\n", best->callcount, best->tprofile, best->tprofile, PRVM_GetString(best->s_name));
+ // %11.6f 12345678901 12345678901 12345678901 %11.6f 12345678901 12345678901 123.45%
+ else
+ Con_Printf("%11.0f %11.6f %11.6f %11.0f %11.0f %11.6f %11.0f %11.0f %6.2f%% %s\n", best->callcount, best->tprofile, best->tbprofile, best->profile, best->builtinsprofile, best->tprofile_total, best->profile_total, best->builtinsprofile_total, (best->tprofile_total > 0) ? ((best->tprofile) * 100.0 / (best->tprofile_total)) : -99.99, PRVM_GetString(best->s_name));
+ }
else
- 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));
+ {
+ if (best->first_statement < 0)
+ Con_Printf("%11.0f ----------------------- builtin ----------------------- %s\n", best->callcount, PRVM_GetString(best->s_name));
+ // 12345678901 12345678901 12345678901 12345678901 123.45%
+ else
+ 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->tprofile = 0;
+ best->tbprofile = 0;
best->builtinsprofile = 0;
best->profile_total = 0;
+ best->tprofile_total = 0;
best->builtinsprofile_total = 0;
best->callcount = 0;
}
if(!PRVM_SetProgFromString(Cmd_Argv(1)))
return;
- PRVM_Profile(howmany, 1, 0);
+ PRVM_Profile(howmany, 0, 0);
PRVM_End;
}
if(!PRVM_SetProgFromString(Cmd_Argv(1)))
return;
- PRVM_Profile(howmany, 1, 1);
+ PRVM_Profile(howmany, 0, 1);
PRVM_End;
}
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].tprofile_acc = -f->tprofile + -f->tbprofile;
prog->stack[prog->depth].builtinsprofile_acc = -f->builtinsprofile;
prog->depth++;
if (prog->depth >=PRVM_MAX_STACK_DEPTH)
--f->recursion;
prog->xfunction = prog->stack[prog->depth].f;
prog->stack[prog->depth].profile_acc += f->profile;
+ prog->stack[prog->depth].tprofile_acc += f->tprofile + f->tbprofile;
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].tprofile_acc += prog->stack[prog->depth].tprofile_acc;
prog->stack[prog->depth-1].builtinsprofile_acc += prog->stack[prog->depth].builtinsprofile_acc;
}
if(!f->recursion)
// 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->tprofile_total += prog->stack[prog->depth].tprofile_acc;
f->builtinsprofile_total += prog->stack[prog->depth].builtinsprofile_acc;
}
int jumpcount, cachedpr_trace, exitdepth;
int restorevm_tempstringsbuf_cursize;
double calltime;
+ double tm, starttm;
calltime = Sys_DoubleTime();
// (when the function exits or jumps, the (st - startst) integer value is
// added to the function's profile counter)
startst = st;
+ starttm = calltime;
// instead of counting instructions, we count jumps
jumpcount = 0;
// add one to the callcount of this function because otherwise engine-called functions aren't counted
if (prvm_statementprofiling.integer || prog->trace)
{
#define PRVMSLOWINTERPRETER 1
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
+#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
#include "prvm_execprogram.h"
+ }
#undef PRVMSLOWINTERPRETER
}
else
{
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
+#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
#include "prvm_execprogram.h"
+ }
}
cleanup:
int jumpcount, cachedpr_trace, exitdepth;
int restorevm_tempstringsbuf_cursize;
double calltime;
+ double tm, starttm;
calltime = Sys_DoubleTime();
// (when the function exits or jumps, the (st - startst) integer value is
// added to the function's profile counter)
startst = st;
+ starttm = calltime;
// instead of counting instructions, we count jumps
jumpcount = 0;
// add one to the callcount of this function because otherwise engine-called functions aren't counted
if (prvm_statementprofiling.integer || prog->trace)
{
#define PRVMSLOWINTERPRETER 1
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
+#include "prvm_execprogram.h"
+ }
#undef PRVMSLOWINTERPRETER
}
else
{
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
+#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
#include "prvm_execprogram.h"
+ }
}
cleanup:
int jumpcount, cachedpr_trace, exitdepth;
int restorevm_tempstringsbuf_cursize;
double calltime;
+ double tm, starttm;
calltime = Sys_DoubleTime();
// (when the function exits or jumps, the (st - startst) integer value is
// added to the function's profile counter)
startst = st;
+ starttm = calltime;
// instead of counting instructions, we count jumps
jumpcount = 0;
// add one to the callcount of this function because otherwise engine-called functions aren't counted
if (prvm_statementprofiling.integer || prog->trace)
{
#define PRVMSLOWINTERPRETER 1
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
+#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
#include "prvm_execprogram.h"
+ }
#undef PRVMSLOWINTERPRETER
}
else
{
+ if (prvm_timeprofiling.integer)
+ {
+#define PRVMTIMEPROFILING 1
+#include "prvm_execprogram.h"
+#undef PRVMTIMEPROFILING
+ }
+ else
+ {
#include "prvm_execprogram.h"
+ }
}
cleanup:
+#ifdef PRVMTIMEPROFILING
+#define PreError() \
+ tm = Sys_DoubleTime(); \
+ prog->xfunction->profile += (st - startst); \
+ prog->xfunction->tprofile += (tm - starttm);
+#else
+#define PreError() \
+ prog->xfunction->profile += (st - startst);
+#endif
// This code isn't #ifdef/#define protectable, don't try.
case OP_STOREP_FNC: // pointers
if (OPB->_int < 0 || OPB->_int + 1 > prog->entityfieldsarea)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("%s attempted to write to an out of bounds edict (%i)", PRVM_NAME, OPB->_int);
goto cleanup;
}
case OP_STOREP_V:
if (OPB->_int < 0 || OPB->_int + 3 > prog->entityfieldsarea)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("%s attempted to write to an out of bounds edict (%i)", PRVM_NAME, OPB->_int);
goto cleanup;
}
case OP_ADDRESS:
if (OPA->edict < 0 || OPA->edict >= prog->max_edicts)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to address an out of bounds edict number", PRVM_NAME);
goto cleanup;
}
if ((unsigned int)(OPB->_int) >= (unsigned int)(prog->progs->entityfields))
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("%s attempted to address an invalid field (%i) in an edict", PRVM_NAME, OPB->_int);
goto cleanup;
}
#if 0
if (OPA->edict == 0 && !prog->allowworldwrites)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("forbidden assignment to null/world entity in %s", PRVM_NAME);
goto cleanup;
}
case OP_LOAD_FNC:
if (OPA->edict < 0 || OPA->edict >= prog->max_edicts)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an out of bounds edict number", PRVM_NAME);
goto cleanup;
}
if ((unsigned int)(OPB->_int) >= (unsigned int)(prog->progs->entityfields))
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("%s attempted to read an invalid field in an edict (%i)", PRVM_NAME, OPB->_int);
goto cleanup;
}
case OP_LOAD_V:
if (OPA->edict < 0 || OPA->edict >= prog->max_edicts)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an out of bounds edict number", PRVM_NAME);
goto cleanup;
}
if (OPB->_int < 0 || OPB->_int + 2 >= prog->progs->entityfields)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR("%s attempted to read an invalid field in an edict (%i)", PRVM_NAME, OPB->_int);
goto cleanup;
}
if (++jumpcount == 10000000 && prvm_runawaycheck)
{
prog->xstatement = st - prog->statements;
- PRVM_Profile(1<<30, 1000000, 0);
+ PRVM_Profile(1<<30, 0.01, 0);
PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount);
}
}
if (++jumpcount == 10000000 && prvm_runawaycheck)
{
prog->xstatement = st - prog->statements;
- PRVM_Profile(1<<30, 1000000, 0);
+ PRVM_Profile(1<<30, 0.01, 0);
PRVM_ERROR("%s runaway loop counter hit limit of %d jumps\ntip: read above for list of most-executed functions", PRVM_NAME, jumpcount);
}
break;
case OP_CALL6:
case OP_CALL7:
case OP_CALL8:
+#ifdef PRVMTIMEPROFILING
+ tm = Sys_DoubleTime();
+ prog->xfunction->tprofile += (tm - starttm);
+ starttm = tm;
+#endif
prog->xfunction->profile += (st - startst);
startst = st;
prog->xstatement = st - prog->statements;
if(!OPA->function || OPA->function >= (unsigned int)prog->progs->numfunctions)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements; // we better stay on the previously executed statement
+ PreError();
PRVM_ERROR("%s CALL outside the program", PRVM_NAME);
goto cleanup;
}
int builtinnumber = -newf->first_statement;
prog->xfunction->builtinsprofile++;
if (builtinnumber < prog->numbuiltins && prog->builtins[builtinnumber])
+ {
prog->builtins[builtinnumber]();
+#ifdef PRVMTIMEPROFILING
+ tm = Sys_DoubleTime();
+ newf->tprofile += (tm - starttm);
+ prog->xfunction->tbprofile += (tm - starttm);
+ starttm = tm;
+#endif
+ }
else
PRVM_ERROR("No such builtin #%i in %s; most likely cause: outdated engine build. Try updating!", builtinnumber, PRVM_NAME);
}
case OP_DONE:
case OP_RETURN:
+#ifdef PRVMTIMEPROFILING
+ tm = Sys_DoubleTime();
+ prog->xfunction->tprofile += (tm - starttm);
+ starttm = tm;
+#endif
prog->xfunction->profile += (st - startst);
prog->xstatement = st - prog->statements;
}
else
{
- prog->xfunction->profile += (st - startst);
+ PreError();
prog->xstatement = st - prog->statements;
PRVM_ERROR("OP_STATE not supported by %s", PRVM_NAME);
}
#if PRBOUNDSCHECK
if (OPB->_int < 0 || OPB->_int + 4 > pr_edictareasize)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to write to an out of bounds edict", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (OPA->edict < 0 || OPA->edict >= prog->max_edicts)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an out of bounds edict number", PRVM_NAME);
goto cleanup;
}
if (OPB->_int < 0 || OPB->_int >= progs->entityfields)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an invalid field in an edict", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (OPB->_int < 0 || OPB->_int >= pr_globaldefs)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to write to an invalid indexed global", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (OPB->_int < 0 || OPB->_int + 2 >= pr_globaldefs)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to write to an invalid indexed global", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (i < 0 || i >= pr_globaldefs)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to address an out of bounds global", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (OPA->_int < 0 || OPA->_int >= pr_globaldefs)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an invalid indexed global", PRVM_NAME);
goto cleanup;
}
#if PRBOUNDSCHECK
if (OPA->_int < 0 || OPA->_int + 2 >= pr_globaldefs)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs attempted to read an invalid indexed global", PRVM_NAME);
goto cleanup;
}
case OP_BOUNDCHECK:
if (OPA->_int < 0 || OPA->_int >= st->b)
{
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("%s Progs boundcheck failed at line number %d, value is < 0 or >= %d", PRVM_NAME, st->b, st->c);
goto cleanup;
}
*/
default:
- prog->xfunction->profile += (st - startst);
- prog->xstatement = st - prog->statements;
+ PreError();
PRVM_ERROR ("Bad opcode %i in %s", st->op, PRVM_NAME);
goto cleanup;
}
}
+#undef PreError
projects / xonotic / darkplaces.git / commitdiff