added amb256 - (nice number), profiler complete with gui to show files

--HG--
extra : convert_revision : svn%3A39bc706e-5318-0410-9160-8a85361fbb7c/trunk%401914

core/Profiler.cpp

@@ -0,0 +1,483 @@
+/**
+ * vim: set ts=4 :
+ * =============================================================================
+ * SourceMod
+ * Copyright (C) 2004-2007 AlliedModders LLC.  All rights reserved.
+ * =============================================================================
+ *
+ * This program is free software; you can redistribute it and/or modify it under
+ * the terms of the GNU General Public License, version 3.0, as published by the
+ * Free Software Foundation.
+ * 
+ * This program is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
+ * FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
+ * details.
+ *
+ * You should have received a copy of the GNU General Public License along with
+ * this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * As a special exception, AlliedModders LLC gives you permission to link the
+ * code of this program (as well as its derivative works) to "Half-Life 2," the
+ * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software
+ * by the Valve Corporation.  You must obey the GNU General Public License in
+ * all respects for all other code used.  Additionally, AlliedModders LLC grants
+ * this exception to all derivative works.  AlliedModders LLC defines further
+ * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007),
+ * or <http://www.sourcemod.net/license.php>.
+ *
+ * Version: $Id$
+ */
+
+#include "Profiler.h"
+#include "PluginSys.h"
+#include "sm_stringutil.h"
+#include "Logger.h"
+
+ProfileEngine g_Profiler;
+IProfiler *sm_profiler = &g_Profiler;
+
+#if defined PLATFORM_WINDOWS
+double WINDOWS_PERFORMANCE_FREQUENCY;
+#endif
+
+class EmptyProfiler : public IProfiler
+{
+public:
+	void OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
+	{
+	}
+	void OnNativeEnd()
+	{
+	}
+	void OnFunctionBegin(IPluginContext *pContext, const char *name)
+	{
+	}
+	void OnFunctionEnd()
+	{
+	}
+	int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
+	{
+		return 0;
+	}
+	void OnCallbackEnd(int serial)
+	{
+	}
+} s_EmptyProfiler;
+
+inline void InitProfPoint(prof_point_t &pt)
+{
+#if defined PLATFORM_WINDOWS
+	QueryPerformanceCounter(&pt.value);
+#elif defined PLATFORM_POSIX
+	gettimeofday(&pt.value, NULL);
+#endif
+	pt.is_set = true;
+}
+
+ProfileEngine::ProfileEngine()
+{
+	m_serial = 0;
+
+#if defined PLATFORM_WINDOWS
+	LARGE_INTEGER pf;
+
+	if (QueryPerformanceFrequency(&pf))
+	{
+		WINDOWS_PERFORMANCE_FREQUENCY = 1.0 / (double)(pf.QuadPart);
+	}
+	else
+	{
+		WINDOWS_PERFORMANCE_FREQUENCY = -1.0;
+	}
+#endif
+
+	if (IsEnabled())
+	{
+		InitProfPoint(m_ProfStart);
+	}
+	else
+	{
+		sm_profiler = &s_EmptyProfiler;
+	}
+}
+
+bool ProfileEngine::IsEnabled()
+{
+#if defined PLATFORM_WINDOWS
+	return (WINDOWS_PERFORMANCE_FREQUENCY > 0.0);
+#elif defined PLATFORM_POSIX
+	return true;
+#endif
+}
+
+inline double DiffProfPoints(const prof_point_t &start, const prof_point_t &end)
+{
+	double seconds;
+
+#if defined PLATFORM_WINDOWS
+	LONGLONG diff;
+	
+	diff = end.value.QuadPart - start.value.QuadPart;
+	seconds = diff * WINDOWS_PERFORMANCE_FREQUENCY;
+#elif defined PLATFORM_POSIX
+	seconds = (double)(end.value.tv_sec - start.value.tv_sec);
+
+	if (start.value.tv_usec > after.value.tv_usec)
+	{
+		seconds - 1.0;
+		seconds += (double)(1000000 - (before.value.tv_usec - after.tv_usec)) / 1000000.0;
+	}
+	else
+	{
+		seconds += (double)(after.value.tv_usec - before.value.tv_usec) / 1000000.0;
+	}
+#endif
+
+	return seconds;
+}
+
+inline double CalcAtomTime(const prof_atom_t &atom)
+{
+	if (!atom.end.is_set)
+	{
+		return atom.base_time;
+	}
+
+	return atom.base_time + DiffProfPoints(atom.start, atom.end);
+}
+
+void ProfileEngine::OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
+{
+	PushProfileStack(pContext, SP_PROF_NATIVES, native->name);
+}
+
+void ProfileEngine::OnNativeEnd()
+{
+	assert(!m_AtomStack.empty());
+	assert(m_AtomStack.front().atom_type == SP_PROF_NATIVES);
+
+	PopProfileStack(&m_Natives);
+}
+
+void ProfileEngine::OnFunctionBegin(IPluginContext *pContext, const char *name)
+{
+	PushProfileStack(pContext, SP_PROF_FUNCTIONS, name);
+}
+
+void ProfileEngine::OnFunctionEnd()
+{
+	assert(!m_AtomStack.empty());
+	assert(m_AtomStack.front().atom_type == SP_PROF_FUNCTIONS);
+
+	PopProfileStack(&m_Functions);
+}
+
+int ProfileEngine::OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
+{
+	PushProfileStack(pContext, SP_PROF_CALLBACKS, pubfunc->name);
+
+	return m_serial;
+}
+
+void ProfileEngine::OnCallbackEnd(int serial)
+{
+	assert(!m_AtomStack.empty());
+
+	/**
+	 * Account for the situation where the JIT discards the 
+	 * stack because there was an RTE of sorts.
+	 */
+	if (m_AtomStack.front().atom_type != SP_PROF_CALLBACKS
+		&& m_AtomStack.front().atom_serial != serial)
+	{
+		prof_atom_t atom;
+		double total_time;
+
+		/* There was an error, and we need to discard things. */
+		total_time = 0.0;
+		while (!m_AtomStack.empty() 
+			&& m_AtomStack.front().atom_type != SP_PROF_CALLBACKS 
+			&& m_AtomStack.front().atom_serial != serial)
+		{
+			total_time += CalcAtomTime(m_AtomStack.front());
+			m_AtomStack.pop();
+		}
+
+		/**
+		 * Now we can end and discard ourselves, without saving the data.
+		 * Since this data is all erroneous anyway, we don't care if it's 
+		 * not totally accurate. 
+		 */
+
+		assert(!m_AtomStack.empty());
+		atom = m_AtomStack.front();
+		m_AtomStack.pop();
+
+		/* Note: We don't need to resume ourselves because end is set by Pause(). */
+		total_time += CalcAtomTime(atom);
+
+		ResumeParent(total_time);
+		return;
+	}
+
+	PopProfileStack(&m_Callbacks);
+}
+
+void ProfileEngine::PushProfileStack(IPluginContext *ctx, int type, const char *name)
+{
+	prof_atom_t atom;
+
+	PauseParent();
+
+	atom.atom_type = type;
+	atom.base_time = 0.0;
+	atom.ctx = ctx->GetContext();
+	atom.name = name;
+	atom.end.is_set = false;
+
+	if (type == SP_PROF_CALLBACKS)
+	{
+		atom.atom_serial = ++m_serial;
+	}
+	else
+	{
+		atom.atom_serial = 0;
+	}
+
+	m_AtomStack.push(atom);
+
+	/* Note: We do this after because the stack could grow and skew results */
+	InitProfPoint(m_AtomStack.front().start);
+}
+
+void ProfileEngine::PopProfileStack(ProfileReport *reporter)
+{
+	double total_time;
+
+	prof_atom_t &atom = m_AtomStack.front();
+
+	/* We're okay to cache our used time. */
+	InitProfPoint(atom.end);
+	total_time = CalcAtomTime(atom);
+
+	/* Now it's time to save this! This may do a lot of computations which 
+	 * is why we've cached the time beforehand.
+	 */
+	reporter->SaveAtom(atom);
+	m_AtomStack.pop();
+
+	/* Finally, tell our parent how much time we used. */
+	ResumeParent(total_time);
+}
+
+void ProfileEngine::PauseParent()
+{
+	if (m_AtomStack.empty())
+	{
+		return;
+	}
+
+	InitProfPoint(m_AtomStack.front().end);
+}
+
+void ProfileEngine::ResumeParent(double addTime)
+{
+	if (m_AtomStack.empty())
+	{
+		return;
+	}
+
+	prof_atom_t &atom = m_AtomStack.front();
+
+	/* Move its "paused time" to its base (known) time, 
+	 * then reset the start/end.  Note that since CalcAtomTime() 
+	 * reads the base time, we SHOULD NOT use += to add.
+	 */
+	atom.base_time = CalcAtomTime(atom);
+	atom.base_time += addTime;
+	InitProfPoint(atom.start);
+	atom.end.is_set = false;
+}
+
+void ProfileEngine::Clear()
+{
+	m_Natives.Clear();
+	m_Callbacks.Clear();
+	m_Functions.Clear();
+	InitProfPoint(m_ProfStart);
+}
+
+void ProfileEngine::OnSourceModAllInitialized()
+{
+	g_RootMenu.AddRootConsoleCommand("profiler", "Profiler commands", this);
+}
+
+void ProfileEngine::OnSourceModShutdown()
+{
+	g_RootMenu.RemoveRootConsoleCommand("profiler", this);
+}
+
+void ProfileEngine::OnRootConsoleCommand(const char *cmdname, const CCommand &command)
+{
+	if (command.ArgC() >= 3)
+	{
+		if (strcmp(command.Arg(2), "flush") == 0)
+		{
+			FILE *fp;
+			char path[256];
+
+			g_SourceMod.BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL));
+
+			if ((fp = fopen(path, "wt")) == NULL)
+			{
+				g_RootMenu.ConsolePrint("Failed, could not open file for writing: %s", path);
+				return;
+			}
+
+			GenerateReport(fp);
+
+			fclose(fp);
+
+			g_RootMenu.ConsolePrint("Profiler report generated as: %s\n", path);
+
+			return;
+		}
+	}
+
+	g_RootMenu.ConsolePrint("Profiler commands:");
+	g_RootMenu.DrawGenericOption("flush", "Flushes statistics to disk and starts over");
+}
+
+bool ProfileEngine::GenerateReport(FILE *fp)
+{
+	time_t t;
+	double total_time;
+	prof_point_t end_time;
+
+	InitProfPoint(end_time);
+	total_time = DiffProfPoints(m_ProfStart, end_time);
+
+	t = time(NULL);
+
+	fprintf(fp, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n\n");
+	fprintf(fp, "<profile time=\"%d\" uptime=\"%f\">\n", (int)t, total_time);
+	WriteReport(fp, &m_Natives, "natives");
+	WriteReport(fp, &m_Callbacks, "callbacks");
+	WriteReport(fp, &m_Functions, "functions");
+	fprintf(fp, "</profile>\n");
+
+	return true;
+}
+
+void ProfileEngine::WriteReport(FILE *fp, ProfileReport *report, const char *name)
+{
+	size_t i, num;
+	prof_atom_report_t *ar;
+	char new_name[512];
+
+	fprintf(fp, " <report name=\"%s\">\n", name);
+	
+	num = report->GetNumReports();
+	for (i = 0; i < num; i++)
+	{
+		ar = report->GetReport(i);
+
+		strncopy(new_name, ar->atom_name, sizeof(new_name));
+		UTIL_ReplaceAll(new_name, sizeof(new_name), "<", "&lt;");
+		UTIL_ReplaceAll(new_name, sizeof(new_name), ">", "&gt;");
+
+		fprintf(fp, "  <item name=\"%s\" numcalls=\"%d\" mintime=\"%f\" maxtime=\"%f\" totaltime=\"%f\"/>\n", 
+			new_name,
+			ar->num_calls,
+			ar->min_time,
+			ar->max_time,
+			ar->total_time);
+	}
+
+	fprintf(fp, " </report>\n");
+}
+
+ProfileReport::~ProfileReport()
+{
+	for (size_t i = 0; i < m_Reports.size(); i++)
+	{
+		delete m_Reports[i];
+	}
+}
+
+void ProfileReport::Clear()
+{
+	m_ReportLookup.clear();
+	for (size_t i = 0; i < m_Reports.size(); i++)
+	{
+		delete m_Reports[i];
+	}
+	m_Reports.clear();
+}
+
+size_t ProfileReport::GetNumReports()
+{
+	return m_Reports.size();
+}
+
+prof_atom_report_t *ProfileReport::GetReport(size_t i)
+{
+	return m_Reports[i];
+}
+
+void ProfileReport::SaveAtom(const prof_atom_t &atom)
+{
+	double atom_time;
+	char full_name[256];
+	prof_atom_report_t **pReport, *report;
+
+	if (atom.atom_type == SP_PROF_NATIVES)
+	{
+		strncopy(full_name, atom.name, sizeof(full_name));
+	}
+	else
+	{
+		CPlugin *pl;
+		const char *file;
+
+		file = "unknown";
+		if ((pl = g_PluginSys.GetPluginByCtx(atom.ctx)) != NULL)
+		{
+			file = pl->GetFilename();
+		}
+
+		UTIL_Format(full_name, sizeof(full_name), "%s!%s", file, atom.name);
+	}
+
+	atom_time = CalcAtomTime(atom);
+
+	if ((pReport = m_ReportLookup.retrieve(full_name)) == NULL)
+	{
+		report = new prof_atom_report_t;
+
+		strncopy(report->atom_name, full_name, sizeof(report->atom_name));
+		report->max_time = atom_time;
+		report->min_time = atom_time;
+		report->num_calls = 1;
+		report->total_time = atom_time;
+		
+		m_ReportLookup.insert(full_name, report);
+		m_Reports.push_back(report);
+	}
+	else
+	{
+		report = *pReport;
+
+		if (atom_time > report->max_time)
+		{
+			report->max_time = atom_time;
+		}
+		if (atom_time < report->min_time)
+		{
+			report->min_time = atom_time;
+		}
+		report->num_calls++;
+		report->total_time += atom_time;
+	}
+}

core/Profiler.h

@@ -0,0 +1,131 @@
+/**
+ * vim: set ts=4 :
+ * =============================================================================
+ * SourceMod
+ * Copyright (C) 2004-2007 AlliedModders LLC.  All rights reserved.
+ * =============================================================================
+ *
+ * This program is free software; you can redistribute it and/or modify it under
+ * the terms of the GNU General Public License, version 3.0, as published by the
+ * Free Software Foundation.
+ * 
+ * This program is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
+ * FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
+ * details.
+ *
+ * You should have received a copy of the GNU General Public License along with
+ * this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * As a special exception, AlliedModders LLC gives you permission to link the
+ * code of this program (as well as its derivative works) to "Half-Life 2," the
+ * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software
+ * by the Valve Corporation.  You must obey the GNU General Public License in
+ * all respects for all other code used.  Additionally, AlliedModders LLC grants
+ * this exception to all derivative works.  AlliedModders LLC defines further
+ * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007),
+ * or <http://www.sourcemod.net/license.php>.
+ *
+ * Version: $Id$
+ */
+
+#ifndef _INCLUDE_SOURCEMOD_PLUGIN_PROFILER_H_
+#define _INCLUDE_SOURCEMOD_PLUGIN_PROFILER_H_
+
+#include <sp_vm_api.h>
+#include <sm_platform.h>
+#include <sm_trie_tpl.h>
+#include <sh_vector.h>
+#include <sh_stack.h>
+#include <stdio.h>
+#include "sm_globals.h"
+#include "sm_srvcmds.h"
+
+using namespace SourcePawn;
+using namespace SourceHook;
+
+struct prof_point_t
+{
+#if defined PLATFORM_WINDOWS
+	LARGE_INTEGER value;
+#elif defined PLATFORM_POSIX
+	struct timeval value;
+#endif
+	bool is_set;
+};
+
+struct prof_atom_t
+{
+	int atom_type;			/* Type of object we're profiling */
+	int atom_serial;		/* Serial number, if appropriate */
+	sp_context_t *ctx;		/* Plugin context. */
+	const char *name;		/* Name of the function */
+	prof_point_t start;		/* Start time */
+	prof_point_t end;		/* End time */
+	double base_time;		/* Known time from children or pausing. */
+};
+
+struct prof_atom_report_t
+{
+	char atom_name[256];	/* Full name to shove to logs */
+	double total_time;		/* Total time spent executing, in s */
+	unsigned int num_calls;	/* Number of invocations */
+	double min_time;		/* Min time spent in one call, in s */
+	double max_time;		/* Max time spent in one call, in s */
+};
+
+class ProfileReport
+{
+public:
+	~ProfileReport();
+public:
+	void SaveAtom(const prof_atom_t &atom);
+	size_t GetNumReports();
+	prof_atom_report_t *GetReport(size_t i);
+	void Clear();
+private:
+	KTrie<prof_atom_report_t *> m_ReportLookup;
+	CVector<prof_atom_report_t *> m_Reports;
+};
+
+class ProfileEngine :
+	public SMGlobalClass,
+	public IRootConsoleCommand,
+	public IProfiler
+{
+public:
+	ProfileEngine();
+public:
+	bool IsEnabled();
+	bool GenerateReport(FILE *fp);
+	void Clear();
+public: //SMGlobalClass
+	void OnSourceModAllInitialized();
+	void OnSourceModShutdown();
+public: //IRootConsoleCommand
+	void OnRootConsoleCommand(const char *cmdname, const CCommand &command);
+public: //IProfiler
+	void OnNativeBegin(IPluginContext *pContext, sp_native_t *native);
+	void OnNativeEnd() ;
+	void OnFunctionBegin(IPluginContext *pContext, const char *name);
+	void OnFunctionEnd();
+	int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc);
+	void OnCallbackEnd(int serial);
+private:
+	void PushProfileStack(IPluginContext *ctx, int type, const char *name);
+	void PopProfileStack(ProfileReport *reporter);
+	void PauseParent();
+	void ResumeParent(double addTime);
+	void WriteReport(FILE *fp, ProfileReport *report, const char *name);
+private:
+	CStack<prof_atom_t> m_AtomStack;
+	ProfileReport m_Callbacks;
+	ProfileReport m_Functions;
+	ProfileReport m_Natives;
+	int m_serial;
+	prof_point_t m_ProfStart;
+};
+
+extern ProfileEngine g_Profiler;
+
+#endif //_INCLUDE_SOURCEMOD_PLUGIN_PROFILER_H_

core/msvc8/sourcemod_mm.vcproj

@@ -1,7 +1,7 @@
 <?xml version="1.0" encoding="Windows-1252"?>
 <VisualStudioProject
 	ProjectType="Visual C++"
-	Version="8,00"
+	Version="8.00"
 	Name="sourcemod_mm"
 	ProjectGUID="{E39527CD-7CAB-4420-97CC-DA1B93B260BC}"
 	RootNamespace="sourcemod_mm"
@@ -723,6 +723,10 @@
 				RelativePath="..\PlayerManager.cpp"
 				>
 			</File>
+			<File
+				RelativePath="..\Profiler.cpp"
+				>
+			</File>
 			<File
 				RelativePath="..\sm_autonatives.cpp"
 				>
@@ -881,6 +885,10 @@
 				RelativePath="..\PlayerManager.h"
 				>
 			</File>
+			<File
+				RelativePath="..\Profiler.h"
+				>
+			</File>
 			<File
 				RelativePath="..\sm_autonatives.h"
 				>

core/systems/PluginSys.cpp

@@ -982,7 +982,6 @@ void CPluginManager::LoadPluginsFromDir(const char *basedir, const char *localpa
 	g_LibSys.CloseDirectory(dir);
 }
 
-//well i have discovered that gabe newell is very fat, so i wrote this comment now
 LoadRes CPluginManager::_LoadPlugin(CPlugin **_plugin, const char *path, bool debug, PluginType type, char error[], size_t maxlength)
 {
 	if (m_LoadingLocked)

core/vm/sp_vm_basecontext.cpp

@@ -61,6 +61,12 @@ BaseContext::BaseContext(sp_context_t *_ctx)
 	ctx = _ctx;
 	ctx->context = this;
 	ctx->dbreak = GlobalDebugBreak;
+
+	if (ctx->prof_flags != 0)
+	{
+		ctx->profiler = sm_profiler;
+	}
+
 	m_InExec = false;
 	m_CustomMsg = false;
 	m_funcsnum = ctx->vmbase->FunctionCount(ctx);
@@ -150,7 +156,7 @@ void BaseContext::RefreshFunctionCache()
 			{
 				continue;
 			}
-			m_pub_funcs[i]->Set(pub->code_offs, this, pub->funcid);
+			m_pub_funcs[i]->Set(pub->code_offs, this, pub->funcid, i);
 		}
 	}
 
@@ -186,9 +192,16 @@ void BaseContext::SetContext(sp_context_t *_ctx)
 	{
 		return;
 	}
+
 	ctx = _ctx;
 	ctx->context = this;
 	ctx->dbreak = GlobalDebugBreak;
+
+	if (ctx->prof_flags != 0)
+	{
+		ctx->profiler = sm_profiler;
+	}
+
 	RefreshFunctionCache();
 }
 
@@ -992,10 +1005,18 @@ IPluginFunction *BaseContext::GetFunctionById(funcid_t func_id)
 		pFunc = m_pub_funcs[func_id];
 		if (!pFunc)
 		{
-			m_pub_funcs[func_id] = new CFunction(ctx->publics[func_id].code_offs, this, ctx->publics[func_id].funcid);
+			m_pub_funcs[func_id] = new CFunction(ctx->publics[func_id].code_offs, 
+												 this, 
+												 ctx->publics[func_id].funcid,
+												 func_id);
 			pFunc = m_pub_funcs[func_id];
-		} else if (pFunc->IsInvalidated()) {
-			pFunc->Set(ctx->publics[func_id].code_offs, this, ctx->publics[func_id].funcid);
+		}
+		else if (pFunc->IsInvalidated())
+		{
+			pFunc->Set(ctx->publics[func_id].code_offs, 
+				       this,
+					   ctx->publics[func_id].funcid,
+					   func_id);
 		}
 	} else {
 		/* :TODO: currently not used */
@@ -1034,16 +1055,20 @@ IPluginFunction *BaseContext::GetFunctionByName(const char *public_name)
 		GetPublicByIndex(index, &pub);
 		if (pub)
 		{
-			m_pub_funcs[index] = new CFunction(pub->code_offs, this, pub->funcid);
+			m_pub_funcs[index] = new CFunction(pub->code_offs, this, pub->funcid, index);
 		}
 		pFunc = m_pub_funcs[index];
-	} else if (pFunc->IsInvalidated()) {
+	}
+	else if (pFunc->IsInvalidated())
+	{
 		sp_public_t *pub = NULL;
 		GetPublicByIndex(index, &pub);
 		if (pub)
 		{
-			pFunc->Set(pub->code_offs, this, pub->funcid);
-		} else {
+			pFunc->Set(pub->code_offs, this, pub->funcid, index);
+		}
+		else
+		{
 			pFunc = NULL;
 		}
 	}

core/vm/sp_vm_basecontext.h

@@ -39,6 +39,8 @@
  * :TODO: Make functions allocate as a lump instead of individual allocations!
  */
 
+extern IProfiler *sm_profiler;
+
 namespace SourcePawn
 {
 	class BaseContext : 

core/vm/sp_vm_function.cpp

@@ -32,12 +32,13 @@
 #include <stdio.h>
 #include <string.h>
 #include "sp_vm_function.h"
+#include "sm_stringutil.h"
 
 /********************
 * FUNCTION CALLING *
 ********************/
 
-void CFunction::Set(uint32_t code_addr, IPluginContext *plugin, funcid_t id)
+void CFunction::Set(uint32_t code_addr, IPluginContext *plugin, funcid_t id, uint32_t pub_id)
 {
 	m_codeaddr = code_addr;
 	m_pContext = plugin;
@@ -46,6 +47,8 @@ void CFunction::Set(uint32_t code_addr, IPluginContext *plugin, funcid_t id)
 	m_Invalid = false;
 	m_pCtx = plugin ? plugin->GetContext() : NULL;
 	m_FnId = id;
+	
+	m_pContext->GetPublicByIndex(pub_id, &m_pPublic);
 }
 
 bool CFunction::IsRunnable()
@@ -55,17 +58,33 @@ bool CFunction::IsRunnable()
 
 int CFunction::CallFunction(const cell_t *params, unsigned int num_params, cell_t *result)
 {
+	int ir, serial;
+
 	if (!IsRunnable())
 	{
 		return SP_ERROR_NOT_RUNNABLE;
 	}
 
+	if ((m_pCtx->prof_flags & SP_PROF_CALLBACKS) == SP_PROF_CALLBACKS
+		&& m_pPublic != NULL)
+	{
+		serial = m_pCtx->profiler->OnCallbackBegin(m_pContext, m_pPublic);
+	}
+
 	while (num_params--)
 	{
 		m_pContext->PushCell(params[num_params]);
 	}
 
-	return m_pContext->Execute(m_codeaddr, result);
+	ir = m_pContext->Execute(m_codeaddr, result);
+
+	if ((m_pCtx->prof_flags & SP_PROF_CALLBACKS) == SP_PROF_CALLBACKS
+		&& m_pPublic != NULL)
+	{
+		m_pCtx->profiler->OnCallbackEnd(serial);
+	}
+
+	return ir;
 }
 
 IPluginContext *CFunction::GetParentContext()
@@ -73,7 +92,7 @@ IPluginContext *CFunction::GetParentContext()
 	return m_pContext;
 }
 
-CFunction::CFunction(uint32_t code_addr, IPluginContext *plugin, funcid_t id) : 
+CFunction::CFunction(uint32_t code_addr, IPluginContext *plugin, funcid_t id, uint32_t pub_id) : 
 	m_codeaddr(code_addr), m_pContext(plugin), m_curparam(0), 
 	m_errorstate(SP_ERROR_NONE), m_FnId(id)
 {
@@ -82,6 +101,7 @@ CFunction::CFunction(uint32_t code_addr, IPluginContext *plugin, funcid_t id) :
 	{
 		m_pCtx = plugin->GetContext();
 	}
+	m_pContext->GetPublicByIndex(pub_id, &m_pPublic);
 }
 
 int CFunction::PushCell(cell_t cell)
@@ -319,3 +339,4 @@ funcid_t CFunction::GetFunctionID()
 {
 	return m_FnId;
 }
+

core/vm/sp_vm_function.h

@@ -55,7 +55,10 @@ class CFunction : public IPluginFunction
 {
 	friend class SourcePawnEngine;
 public:
-	CFunction(uint32_t code_addr, IPluginContext *pContext, funcid_t fnid);
+	CFunction(uint32_t code_addr,
+			  IPluginContext *pContext, 
+			  funcid_t fnid,
+			  uint32_t pub_id);
 public:
 	virtual int PushCell(cell_t cell);
 	virtual int PushCellByRef(cell_t *cell, int flags);
@@ -79,7 +82,7 @@ public:
 	bool IsRunnable();
 	funcid_t GetFunctionID();
 public:
-	void Set(uint32_t code_addr, IPluginContext *plugin, funcid_t fnid);
+	void Set(uint32_t code_addr, IPluginContext *plugin, funcid_t fnid, uint32_t pub_id);
 private:
 	int _PushString(const char *string, int sz_flags, int cp_flags, size_t len);
 	inline int SetError(int err)
@@ -98,6 +101,7 @@ private:
 	CFunction *m_pNext;
 	bool m_Invalid;
 	funcid_t m_FnId;
+	sp_public_t *m_pPublic;
 };
 
 #endif //_INCLUDE_SOURCEMOD_BASEFUNCTION_H_