core/Profiler.cpp
author David Anderson <dvander@alliedmods.net>
Sun Feb 08 15:40:48 2009 -0500 (2009-02-08)
changeset 2571 5c995a647735
parent 2289 44045ead61cd
permissions -rw-r--r--
Fixed documentation typos in dbi.inc (bug 3587).
     1 /**
     2  * vim: set ts=4 :
     3  * =============================================================================
     4  * SourceMod
     5  * Copyright (C) 2004-2008 AlliedModders LLC.  All rights reserved.
     6  * =============================================================================
     7  *
     8  * This program is free software; you can redistribute it and/or modify it under
     9  * the terms of the GNU General Public License, version 3.0, as published by the
    10  * Free Software Foundation.
    11  * 
    12  * This program is distributed in the hope that it will be useful, but WITHOUT
    13  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
    14  * FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
    15  * details.
    16  *
    17  * You should have received a copy of the GNU General Public License along with
    18  * this program.  If not, see <http://www.gnu.org/licenses/>.
    19  *
    20  * As a special exception, AlliedModders LLC gives you permission to link the
    21  * code of this program (as well as its derivative works) to "Half-Life 2," the
    22  * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software
    23  * by the Valve Corporation.  You must obey the GNU General Public License in
    24  * all respects for all other code used.  Additionally, AlliedModders LLC grants
    25  * this exception to all derivative works.  AlliedModders LLC defines further
    26  * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007),
    27  * or <http://www.sourcemod.net/license.php>.
    28  *
    29  * Version: $Id$
    30  */
    31 
    32 #include "Profiler.h"
    33 #include "PluginSys.h"
    34 #include "sm_stringutil.h"
    35 #include "Logger.h"
    36 #if defined PLATFORM_POSIX
    37 #include <sys/time.h>
    38 #include <time.h>
    39 #endif
    40 
    41 ProfileEngine g_Profiler;
    42 IProfiler *sm_profiler = &g_Profiler;
    43 
    44 #if defined PLATFORM_WINDOWS
    45 double WINDOWS_PERFORMANCE_FREQUENCY;
    46 #endif
    47 
    48 class EmptyProfiler : public IProfiler
    49 {
    50 public:
    51 	void OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
    52 	{
    53 	}
    54 	void OnNativeEnd()
    55 	{
    56 	}
    57 	void OnFunctionBegin(IPluginContext *pContext, const char *name)
    58 	{
    59 	}
    60 	void OnFunctionEnd()
    61 	{
    62 	}
    63 	int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
    64 	{
    65 		return 0;
    66 	}
    67 	void OnCallbackEnd(int serial)
    68 	{
    69 	}
    70 } s_EmptyProfiler;
    71 
    72 inline void InitProfPoint(prof_point_t &pt)
    73 {
    74 #if defined PLATFORM_WINDOWS
    75 	QueryPerformanceCounter(&pt.value);
    76 #elif defined PLATFORM_POSIX
    77 	gettimeofday(&pt.value, NULL);
    78 #endif
    79 	pt.is_set = true;
    80 }
    81 
    82 ProfileEngine::ProfileEngine()
    83 {
    84 	m_serial = 0;
    85 
    86 #if defined PLATFORM_WINDOWS
    87 	LARGE_INTEGER pf;
    88 
    89 	if (QueryPerformanceFrequency(&pf))
    90 	{
    91 		WINDOWS_PERFORMANCE_FREQUENCY = 1.0 / (double)(pf.QuadPart);
    92 	}
    93 	else
    94 	{
    95 		WINDOWS_PERFORMANCE_FREQUENCY = -1.0;
    96 	}
    97 #endif
    98 
    99 	if (IsEnabled())
   100 	{
   101 		InitProfPoint(m_ProfStart);
   102 	}
   103 	else
   104 	{
   105 		sm_profiler = &s_EmptyProfiler;
   106 	}
   107 }
   108 
   109 bool ProfileEngine::IsEnabled()
   110 {
   111 #if defined PLATFORM_WINDOWS
   112 	return (WINDOWS_PERFORMANCE_FREQUENCY > 0.0);
   113 #elif defined PLATFORM_POSIX
   114 	return true;
   115 #endif
   116 }
   117 
   118 inline double DiffProfPoints(const prof_point_t &start, const prof_point_t &end)
   119 {
   120 	double seconds;
   121 
   122 #if defined PLATFORM_WINDOWS
   123 	LONGLONG diff;
   124 	
   125 	diff = end.value.QuadPart - start.value.QuadPart;
   126 	seconds = diff * WINDOWS_PERFORMANCE_FREQUENCY;
   127 #elif defined PLATFORM_POSIX
   128 	seconds = (double)(end.value.tv_sec - start.value.tv_sec);
   129 
   130 	if (start.value.tv_usec > end.value.tv_usec)
   131 	{
   132 		seconds -= 1.0;
   133 		seconds += (double)(1000000 - (start.value.tv_usec - end.value.tv_usec)) / 1000000.0;
   134 	}
   135 	else
   136 	{
   137 		seconds += (double)(end.value.tv_usec - start.value.tv_usec) / 1000000.0;
   138 	}
   139 #endif
   140 
   141 	return seconds;
   142 }
   143 
   144 inline double CalcAtomTime(const prof_atom_t &atom)
   145 {
   146 	if (!atom.end.is_set)
   147 	{
   148 		return atom.base_time;
   149 	}
   150 
   151 	return atom.base_time + DiffProfPoints(atom.start, atom.end);
   152 }
   153 
   154 void ProfileEngine::OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
   155 {
   156 	PushProfileStack(pContext, SP_PROF_NATIVES, native->name);
   157 }
   158 
   159 void ProfileEngine::OnNativeEnd()
   160 {
   161 	assert(!m_AtomStack.empty());
   162 	assert(m_AtomStack.front().atom_type == SP_PROF_NATIVES);
   163 
   164 	PopProfileStack(&m_Natives);
   165 }
   166 
   167 void ProfileEngine::OnFunctionBegin(IPluginContext *pContext, const char *name)
   168 {
   169 	PushProfileStack(pContext, SP_PROF_FUNCTIONS, name);
   170 }
   171 
   172 void ProfileEngine::OnFunctionEnd()
   173 {
   174 	assert(!m_AtomStack.empty());
   175 	assert(m_AtomStack.front().atom_type == SP_PROF_FUNCTIONS);
   176 
   177 	PopProfileStack(&m_Functions);
   178 }
   179 
   180 int ProfileEngine::OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
   181 {
   182 	PushProfileStack(pContext, SP_PROF_CALLBACKS, pubfunc->name);
   183 
   184 	return m_serial;
   185 }
   186 
   187 void ProfileEngine::OnCallbackEnd(int serial)
   188 {
   189 	assert(!m_AtomStack.empty());
   190 
   191 	/**
   192 	 * Account for the situation where the JIT discards the 
   193 	 * stack because there was an RTE of sorts.
   194 	 */
   195 	if (m_AtomStack.front().atom_type != SP_PROF_CALLBACKS
   196 		&& m_AtomStack.front().atom_serial != serial)
   197 	{
   198 		prof_atom_t atom;
   199 		double total_time;
   200 
   201 		/* There was an error, and we need to discard things. */
   202 		total_time = 0.0;
   203 		while (!m_AtomStack.empty() 
   204 			&& m_AtomStack.front().atom_type != SP_PROF_CALLBACKS 
   205 			&& m_AtomStack.front().atom_serial != serial)
   206 		{
   207 			total_time += CalcAtomTime(m_AtomStack.front());
   208 			m_AtomStack.pop();
   209 		}
   210 
   211 		/**
   212 		 * Now we can end and discard ourselves, without saving the data.
   213 		 * Since this data is all erroneous anyway, we don't care if it's 
   214 		 * not totally accurate. 
   215 		 */
   216 
   217 		assert(!m_AtomStack.empty());
   218 		atom = m_AtomStack.front();
   219 		m_AtomStack.pop();
   220 
   221 		/* Note: We don't need to resume ourselves because end is set by Pause(). */
   222 		total_time += CalcAtomTime(atom);
   223 
   224 		ResumeParent(total_time);
   225 		return;
   226 	}
   227 
   228 	PopProfileStack(&m_Callbacks);
   229 }
   230 
   231 void ProfileEngine::PushProfileStack(IPluginContext *ctx, int type, const char *name)
   232 {
   233 	prof_atom_t atom;
   234 
   235 	PauseParent();
   236 
   237 	atom.atom_type = type;
   238 	atom.base_time = 0.0;
   239 	atom.ctx = ctx->GetContext();
   240 	atom.name = name;
   241 	atom.end.is_set = false;
   242 
   243 	if (type == SP_PROF_CALLBACKS)
   244 	{
   245 		atom.atom_serial = ++m_serial;
   246 	}
   247 	else
   248 	{
   249 		atom.atom_serial = 0;
   250 	}
   251 
   252 	m_AtomStack.push(atom);
   253 
   254 	/* Note: We do this after because the stack could grow and skew results */
   255 	InitProfPoint(m_AtomStack.front().start);
   256 }
   257 
   258 void ProfileEngine::PopProfileStack(ProfileReport *reporter)
   259 {
   260 	double total_time;
   261 
   262 	prof_atom_t &atom = m_AtomStack.front();
   263 
   264 	/* We're okay to cache our used time. */
   265 	InitProfPoint(atom.end);
   266 	total_time = CalcAtomTime(atom);
   267 
   268 	/* Now it's time to save this! This may do a lot of computations which 
   269 	 * is why we've cached the time beforehand.
   270 	 */
   271 	reporter->SaveAtom(atom);
   272 	m_AtomStack.pop();
   273 
   274 	/* Finally, tell our parent how much time we used. */
   275 	ResumeParent(total_time);
   276 }
   277 
   278 void ProfileEngine::PauseParent()
   279 {
   280 	if (m_AtomStack.empty())
   281 	{
   282 		return;
   283 	}
   284 
   285 	InitProfPoint(m_AtomStack.front().end);
   286 }
   287 
   288 void ProfileEngine::ResumeParent(double addTime)
   289 {
   290 	if (m_AtomStack.empty())
   291 	{
   292 		return;
   293 	}
   294 
   295 	prof_atom_t &atom = m_AtomStack.front();
   296 
   297 	/* Move its "paused time" to its base (known) time, 
   298 	 * then reset the start/end.  Note that since CalcAtomTime() 
   299 	 * reads the base time, we SHOULD NOT use += to add.
   300 	 */
   301 	atom.base_time = CalcAtomTime(atom);
   302 	atom.base_time += addTime;
   303 	InitProfPoint(atom.start);
   304 	atom.end.is_set = false;
   305 }
   306 
   307 void ProfileEngine::Clear()
   308 {
   309 	m_Natives.Clear();
   310 	m_Callbacks.Clear();
   311 	m_Functions.Clear();
   312 	InitProfPoint(m_ProfStart);
   313 }
   314 
   315 void ProfileEngine::OnSourceModAllInitialized()
   316 {
   317 	g_RootMenu.AddRootConsoleCommand("profiler", "Profiler commands", this);
   318 }
   319 
   320 void ProfileEngine::OnSourceModShutdown()
   321 {
   322 	g_RootMenu.RemoveRootConsoleCommand("profiler", this);
   323 }
   324 
   325 void ProfileEngine::OnRootConsoleCommand(const char *cmdname, const CCommand &command)
   326 {
   327 	if (command.ArgC() >= 3)
   328 	{
   329 		if (strcmp(command.Arg(2), "flush") == 0)
   330 		{
   331 			FILE *fp;
   332 			char path[256];
   333 
   334 			g_SourceMod.BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL));
   335 
   336 			if ((fp = fopen(path, "wt")) == NULL)
   337 			{
   338 				g_RootMenu.ConsolePrint("Failed, could not open file for writing: %s", path);
   339 				return;
   340 			}
   341 
   342 			GenerateReport(fp);
   343 
   344 			fclose(fp);
   345 
   346 			g_RootMenu.ConsolePrint("Profiler report generated as: %s\n", path);
   347 
   348 			return;
   349 		}
   350 	}
   351 
   352 	g_RootMenu.ConsolePrint("Profiler commands:");
   353 	g_RootMenu.DrawGenericOption("flush", "Flushes statistics to disk and starts over");
   354 }
   355 
   356 bool ProfileEngine::GenerateReport(FILE *fp)
   357 {
   358 	time_t t;
   359 	double total_time;
   360 	prof_point_t end_time;
   361 
   362 	InitProfPoint(end_time);
   363 	total_time = DiffProfPoints(m_ProfStart, end_time);
   364 
   365 	t = time(NULL);
   366 
   367 	fprintf(fp, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n\n");
   368 	fprintf(fp, "<profile time=\"%d\" uptime=\"%f\">\n", (int)t, total_time);
   369 	WriteReport(fp, &m_Natives, "natives");
   370 	WriteReport(fp, &m_Callbacks, "callbacks");
   371 	WriteReport(fp, &m_Functions, "functions");
   372 	fprintf(fp, "</profile>\n");
   373 
   374 	return true;
   375 }
   376 
   377 void ProfileEngine::WriteReport(FILE *fp, ProfileReport *report, const char *name)
   378 {
   379 	size_t i, num;
   380 	prof_atom_report_t *ar;
   381 	char new_name[512];
   382 
   383 	fprintf(fp, " <report name=\"%s\">\n", name);
   384 	
   385 	num = report->GetNumReports();
   386 	for (i = 0; i < num; i++)
   387 	{
   388 		ar = report->GetReport(i);
   389 
   390 		strncopy(new_name, ar->atom_name, sizeof(new_name));
   391 		UTIL_ReplaceAll(new_name, sizeof(new_name), "<", "&lt;");
   392 		UTIL_ReplaceAll(new_name, sizeof(new_name), ">", "&gt;");
   393 
   394 		fprintf(fp, "  <item name=\"%s\" numcalls=\"%d\" mintime=\"%f\" maxtime=\"%f\" totaltime=\"%f\"/>\n", 
   395 			new_name,
   396 			ar->num_calls,
   397 			ar->min_time,
   398 			ar->max_time,
   399 			ar->total_time);
   400 	}
   401 
   402 	fprintf(fp, " </report>\n");
   403 }
   404 
   405 ProfileReport::~ProfileReport()
   406 {
   407 	for (size_t i = 0; i < m_Reports.size(); i++)
   408 	{
   409 		delete m_Reports[i];
   410 	}
   411 }
   412 
   413 void ProfileReport::Clear()
   414 {
   415 	m_ReportLookup.clear();
   416 	for (size_t i = 0; i < m_Reports.size(); i++)
   417 	{
   418 		delete m_Reports[i];
   419 	}
   420 	m_Reports.clear();
   421 }
   422 
   423 size_t ProfileReport::GetNumReports()
   424 {
   425 	return m_Reports.size();
   426 }
   427 
   428 prof_atom_report_t *ProfileReport::GetReport(size_t i)
   429 {
   430 	return m_Reports[i];
   431 }
   432 
   433 void ProfileReport::SaveAtom(const prof_atom_t &atom)
   434 {
   435 	double atom_time;
   436 	char full_name[256];
   437 	prof_atom_report_t **pReport, *report;
   438 
   439 	if (atom.atom_type == SP_PROF_NATIVES)
   440 	{
   441 		strncopy(full_name, atom.name, sizeof(full_name));
   442 	}
   443 	else
   444 	{
   445 		CPlugin *pl;
   446 		const char *file;
   447 
   448 		file = "unknown";
   449 		if ((pl = g_PluginSys.GetPluginByCtx(atom.ctx)) != NULL)
   450 		{
   451 			file = pl->GetFilename();
   452 		}
   453 
   454 		UTIL_Format(full_name, sizeof(full_name), "%s!%s", file, atom.name);
   455 	}
   456 
   457 	atom_time = CalcAtomTime(atom);
   458 
   459 	if ((pReport = m_ReportLookup.retrieve(full_name)) == NULL)
   460 	{
   461 		report = new prof_atom_report_t;
   462 
   463 		strncopy(report->atom_name, full_name, sizeof(report->atom_name));
   464 		report->max_time = atom_time;
   465 		report->min_time = atom_time;
   466 		report->num_calls = 1;
   467 		report->total_time = atom_time;
   468 		
   469 		m_ReportLookup.insert(full_name, report);
   470 		m_Reports.push_back(report);
   471 	}
   472 	else
   473 	{
   474 		report = *pReport;
   475 
   476 		if (atom_time > report->max_time)
   477 		{
   478 			report->max_time = atom_time;
   479 		}
   480 		if (atom_time < report->min_time)
   481 		{
   482 			report->min_time = atom_time;
   483 		}
   484 		report->num_calls++;
   485 		report->total_time += atom_time;
   486 	}
   487 }