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