From: divverent <divverent@d7cf8633-e32d-0410-b094-e92efae38249>
Date: Fri, 19 Oct 2007 10:51:33 +0000 (+0000)
Subject: prvm_callprofile: a flat profile, time based, including subcalls
X-Git-Tag: xonotic-v0.1.0preview~2834
X-Git-Url: https://git.rm.cloudns.org/?a=commitdiff_plain;h=2a28f051d86861fb4656d3a46c40bf2a736b21e5;p=xonotic%2Fdarkplaces.git

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 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 ; 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();
 }