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