core/logic/Profiler.cpp
author Nicholas Hastings <skamonkey@gmail.com>
Mon Feb 08 19:57:20 2010 -0800 (2010-02-08)
changeset 2914 bf5f9aa53abe
parent 2728 96022dad7e53
child 3005 2db965f8db3f
permissions -rw-r--r--
Fixed FindEntityByClassname crash in Synergy (bug 4235, r=dvander).
     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 <ISourceMod.h>
    34 #if defined PLATFORM_POSIX
    35 #include <sys/time.h>
    36 #include <time.h>
    37 #endif
    38 #include <IPluginSys.h>
    39 
    40 ProfileEngine g_Profiler;
    41 IProfiler *sm_profiler = &g_Profiler;
    42 
    43 #if defined PLATFORM_WINDOWS
    44 double WINDOWS_PERFORMANCE_FREQUENCY;
    45 #endif
    46 
    47 class EmptyProfiler : public IProfiler
    48 {
    49 public:
    50 	void OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
    51 	{
    52 	}
    53 	void OnNativeEnd()
    54 	{
    55 	}
    56 	void OnFunctionBegin(IPluginContext *pContext, const char *name)
    57 	{
    58 	}
    59 	void OnFunctionEnd()
    60 	{
    61 	}
    62 	int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
    63 	{
    64 		return 0;
    65 	}
    66 	void OnCallbackEnd(int serial)
    67 	{
    68 	}
    69 } s_EmptyProfiler;
    70 
    71 inline void InitProfPoint(prof_point_t &pt)
    72 {
    73 #if defined PLATFORM_WINDOWS
    74 	QueryPerformanceCounter(&pt.value);
    75 #elif defined PLATFORM_POSIX
    76 	gettimeofday(&pt.value, NULL);
    77 #endif
    78 	pt.is_set = true;
    79 }
    80 
    81 ProfileEngine::ProfileEngine()
    82 {
    83 	m_serial = 0;
    84 
    85 #if defined PLATFORM_WINDOWS
    86 	LARGE_INTEGER pf;
    87 
    88 	if (QueryPerformanceFrequency(&pf))
    89 	{
    90 		WINDOWS_PERFORMANCE_FREQUENCY = 1.0 / (double)(pf.QuadPart);
    91 	}
    92 	else
    93 	{
    94 		WINDOWS_PERFORMANCE_FREQUENCY = -1.0;
    95 	}
    96 #endif
    97 
    98 	if (IsEnabled())
    99 	{
   100 		InitProfPoint(m_ProfStart);
   101 	}
   102 	else
   103 	{
   104 		sm_profiler = &s_EmptyProfiler;
   105 	}
   106 }
   107 
   108 bool ProfileEngine::IsEnabled()
   109 {
   110 #if defined PLATFORM_WINDOWS
   111 	return (WINDOWS_PERFORMANCE_FREQUENCY > 0.0);
   112 #elif defined PLATFORM_POSIX
   113 	return true;
   114 #endif
   115 }
   116 
   117 inline double DiffProfPoints(const prof_point_t &start, const prof_point_t &end)
   118 {
   119 	double seconds;
   120 
   121 #if defined PLATFORM_WINDOWS
   122 	LONGLONG diff;
   123 	
   124 	diff = end.value.QuadPart - start.value.QuadPart;
   125 	seconds = diff * WINDOWS_PERFORMANCE_FREQUENCY;
   126 #elif defined PLATFORM_POSIX
   127 	seconds = (double)(end.value.tv_sec - start.value.tv_sec);
   128 
   129 	if (start.value.tv_usec > end.value.tv_usec)
   130 	{
   131 		seconds -= 1.0;
   132 		seconds += (double)(1000000 - (start.value.tv_usec - end.value.tv_usec)) / 1000000.0;
   133 	}
   134 	else
   135 	{
   136 		seconds += (double)(end.value.tv_usec - start.value.tv_usec) / 1000000.0;
   137 	}
   138 #endif
   139 
   140 	return seconds;
   141 }
   142 
   143 inline double CalcAtomTime(const prof_atom_t &atom)
   144 {
   145 	if (!atom.end.is_set)
   146 	{
   147 		return atom.base_time;
   148 	}
   149 
   150 	return atom.base_time + DiffProfPoints(atom.start, atom.end);
   151 }
   152 
   153 void ProfileEngine::OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
   154 {
   155 	PushProfileStack(pContext, SP_PROF_NATIVES, native->name);
   156 }
   157 
   158 void ProfileEngine::OnNativeEnd()
   159 {
   160 	assert(!m_AtomStack.empty());
   161 	assert(m_AtomStack.front().atom_type == SP_PROF_NATIVES);
   162 
   163 	PopProfileStack(&m_Natives);
   164 }
   165 
   166 void ProfileEngine::OnFunctionBegin(IPluginContext *pContext, const char *name)
   167 {
   168 	PushProfileStack(pContext, SP_PROF_FUNCTIONS, name);
   169 }
   170 
   171 void ProfileEngine::OnFunctionEnd()
   172 {
   173 	assert(!m_AtomStack.empty());
   174 	assert(m_AtomStack.front().atom_type == SP_PROF_FUNCTIONS);
   175 
   176 	PopProfileStack(&m_Functions);
   177 }
   178 
   179 int ProfileEngine::OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
   180 {
   181 	PushProfileStack(pContext, SP_PROF_CALLBACKS, pubfunc->name);
   182 
   183 	return m_serial;
   184 }
   185 
   186 void ProfileEngine::OnCallbackEnd(int serial)
   187 {
   188 	assert(!m_AtomStack.empty());
   189 
   190 	/**
   191 	 * Account for the situation where the JIT discards the 
   192 	 * stack because there was an RTE of sorts.
   193 	 */
   194 	if (m_AtomStack.front().atom_type != SP_PROF_CALLBACKS
   195 		&& m_AtomStack.front().atom_serial != serial)
   196 	{
   197 		prof_atom_t atom;
   198 		double total_time;
   199 
   200 		/* There was an error, and we need to discard things. */
   201 		total_time = 0.0;
   202 		while (!m_AtomStack.empty() 
   203 			&& m_AtomStack.front().atom_type != SP_PROF_CALLBACKS 
   204 			&& m_AtomStack.front().atom_serial != serial)
   205 		{
   206 			total_time += CalcAtomTime(m_AtomStack.front());
   207 			m_AtomStack.pop();
   208 		}
   209 
   210 		/**
   211 		 * Now we can end and discard ourselves, without saving the data.
   212 		 * Since this data is all erroneous anyway, we don't care if it's 
   213 		 * not totally accurate. 
   214 		 */
   215 
   216 		assert(!m_AtomStack.empty());
   217 		atom = m_AtomStack.front();
   218 		m_AtomStack.pop();
   219 
   220 		/* Note: We don't need to resume ourselves because end is set by Pause(). */
   221 		total_time += CalcAtomTime(atom);
   222 
   223 		ResumeParent(total_time);
   224 		return;
   225 	}
   226 
   227 	PopProfileStack(&m_Callbacks);
   228 }
   229 
   230 void ProfileEngine::PushProfileStack(IPluginContext *ctx, int type, const char *name)
   231 {
   232 	prof_atom_t atom;
   233 
   234 	PauseParent();
   235 
   236 	atom.atom_type = type;
   237 	atom.base_time = 0.0;
   238 	atom.ctx = ctx->GetContext();
   239 	atom.name = name;
   240 	atom.end.is_set = false;
   241 
   242 	if (type == SP_PROF_CALLBACKS)
   243 	{
   244 		atom.atom_serial = ++m_serial;
   245 	}
   246 	else
   247 	{
   248 		atom.atom_serial = 0;
   249 	}
   250 
   251 	m_AtomStack.push(atom);
   252 
   253 	/* Note: We do this after because the stack could grow and skew results */
   254 	InitProfPoint(m_AtomStack.front().start);
   255 }
   256 
   257 void ProfileEngine::PopProfileStack(ProfileReport *reporter)
   258 {
   259 	double total_time;
   260 
   261 	prof_atom_t &atom = m_AtomStack.front();
   262 
   263 	/* We're okay to cache our used time. */
   264 	InitProfPoint(atom.end);
   265 	total_time = CalcAtomTime(atom);
   266 
   267 	/* Now it's time to save this! This may do a lot of computations which 
   268 	 * is why we've cached the time beforehand.
   269 	 */
   270 	reporter->SaveAtom(atom);
   271 	m_AtomStack.pop();
   272 
   273 	/* Finally, tell our parent how much time we used. */
   274 	ResumeParent(total_time);
   275 }
   276 
   277 void ProfileEngine::PauseParent()
   278 {
   279 	if (m_AtomStack.empty())
   280 	{
   281 		return;
   282 	}
   283 
   284 	InitProfPoint(m_AtomStack.front().end);
   285 }
   286 
   287 void ProfileEngine::ResumeParent(double addTime)
   288 {
   289 	if (m_AtomStack.empty())
   290 	{
   291 		return;
   292 	}
   293 
   294 	prof_atom_t &atom = m_AtomStack.front();
   295 
   296 	/* Move its "paused time" to its base (known) time, 
   297 	 * then reset the start/end.  Note that since CalcAtomTime() 
   298 	 * reads the base time, we SHOULD NOT use += to add.
   299 	 */
   300 	atom.base_time = CalcAtomTime(atom);
   301 	atom.base_time += addTime;
   302 	InitProfPoint(atom.start);
   303 	atom.end.is_set = false;
   304 }
   305 
   306 void ProfileEngine::Clear()
   307 {
   308 	m_Natives.Clear();
   309 	m_Callbacks.Clear();
   310 	m_Functions.Clear();
   311 	InitProfPoint(m_ProfStart);
   312 }
   313 
   314 void ProfileEngine::OnSourceModAllInitialized()
   315 {
   316 	rootmenu->AddRootConsoleCommand2("profiler", "Profiler commands", this);
   317 }
   318 
   319 void ProfileEngine::OnSourceModShutdown()
   320 {
   321 	rootmenu->RemoveRootConsoleCommand("profiler", this);
   322 }
   323 
   324 void ProfileEngine::OnRootConsoleCommand2(const char *cmdname, const ICommandArgs *command)
   325 {
   326 	if (command->ArgC() >= 3)
   327 	{
   328 		if (strcmp(command->Arg(2), "flush") == 0)
   329 		{
   330 			FILE *fp;
   331 			char path[256];
   332 
   333 			g_pSM->BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL));
   334 
   335 			if ((fp = fopen(path, "wt")) == NULL)
   336 			{
   337 				rootmenu->ConsolePrint("Failed, could not open file for writing: %s", path);
   338 				return;
   339 			}
   340 
   341 			GenerateReport(fp);
   342 
   343 			fclose(fp);
   344 
   345 			rootmenu->ConsolePrint("Profiler report generated as: %s\n", path);
   346 
   347 			return;
   348 		}
   349 	}
   350 
   351 	rootmenu->ConsolePrint("Profiler commands:");
   352 	rootmenu->DrawGenericOption("flush", "Flushes statistics to disk and starts over");
   353 }
   354 
   355 bool ProfileEngine::GenerateReport(FILE *fp)
   356 {
   357 	time_t t;
   358 	double total_time;
   359 	prof_point_t end_time;
   360 
   361 	InitProfPoint(end_time);
   362 	total_time = DiffProfPoints(m_ProfStart, end_time);
   363 
   364 	t = time(NULL);
   365 
   366 	fprintf(fp, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n\n");
   367 	fprintf(fp, "<profile time=\"%d\" uptime=\"%f\">\n", (int)t, total_time);
   368 	WriteReport(fp, &m_Natives, "natives");
   369 	WriteReport(fp, &m_Callbacks, "callbacks");
   370 	WriteReport(fp, &m_Functions, "functions");
   371 	fprintf(fp, "</profile>\n");
   372 
   373 	return true;
   374 }
   375 
   376 void ProfileEngine::WriteReport(FILE *fp, ProfileReport *report, const char *name)
   377 {
   378 	size_t i, num;
   379 	prof_atom_report_t *ar;
   380 	char new_name[512];
   381 
   382 	fprintf(fp, " <report name=\"%s\">\n", name);
   383 	
   384 	num = report->GetNumReports();
   385 	for (i = 0; i < num; i++)
   386 	{
   387 		ar = report->GetReport(i);
   388 
   389 		smcore.strncopy(new_name, ar->atom_name, sizeof(new_name));
   390 		smcore.ReplaceAll(new_name, sizeof(new_name), "<", "&lt;", true);
   391 		smcore.ReplaceAll(new_name, sizeof(new_name), ">", "&gt;", true);
   392 
   393 		fprintf(fp, "  <item name=\"%s\" numcalls=\"%d\" mintime=\"%f\" maxtime=\"%f\" totaltime=\"%f\"/>\n", 
   394 			new_name,
   395 			ar->num_calls,
   396 			ar->min_time,
   397 			ar->max_time,
   398 			ar->total_time);
   399 	}
   400 
   401 	fprintf(fp, " </report>\n");
   402 }
   403 
   404 ProfileReport::~ProfileReport()
   405 {
   406 	for (size_t i = 0; i < m_Reports.size(); i++)
   407 	{
   408 		delete m_Reports[i];
   409 	}
   410 }
   411 
   412 void ProfileReport::Clear()
   413 {
   414 	m_ReportLookup.clear();
   415 	for (size_t i = 0; i < m_Reports.size(); i++)
   416 	{
   417 		delete m_Reports[i];
   418 	}
   419 	m_Reports.clear();
   420 }
   421 
   422 size_t ProfileReport::GetNumReports()
   423 {
   424 	return m_Reports.size();
   425 }
   426 
   427 prof_atom_report_t *ProfileReport::GetReport(size_t i)
   428 {
   429 	return m_Reports[i];
   430 }
   431 
   432 void ProfileReport::SaveAtom(const prof_atom_t &atom)
   433 {
   434 	double atom_time;
   435 	char full_name[256];
   436 	prof_atom_report_t **pReport, *report;
   437 
   438 	if (atom.atom_type == SP_PROF_NATIVES)
   439 	{
   440 		smcore.strncopy(full_name, atom.name, sizeof(full_name));
   441 	}
   442 	else
   443 	{
   444 		IPlugin *pl;
   445 		const char *file;
   446 
   447 		file = "unknown";
   448 		if ((pl = pluginsys->FindPluginByContext(atom.ctx)) != NULL)
   449 		{
   450 			file = pl->GetFilename();
   451 		}
   452 
   453 		smcore.Format(full_name, sizeof(full_name), "%s!%s", file, atom.name);
   454 	}
   455 
   456 	atom_time = CalcAtomTime(atom);
   457 
   458 	if ((pReport = m_ReportLookup.retrieve(full_name)) == NULL)
   459 	{
   460 		report = new prof_atom_report_t;
   461 
   462 		smcore.strncopy(report->atom_name, full_name, sizeof(report->atom_name));
   463 		report->max_time = atom_time;
   464 		report->min_time = atom_time;
   465 		report->num_calls = 1;
   466 		report->total_time = atom_time;
   467 		
   468 		m_ReportLookup.insert(full_name, report);
   469 		m_Reports.push_back(report);
   470 	}
   471 	else
   472 	{
   473 		report = *pReport;
   474 
   475 		if (atom_time > report->max_time)
   476 		{
   477 			report->max_time = atom_time;
   478 		}
   479 		if (atom_time < report->min_time)
   480 		{
   481 			report->min_time = atom_time;
   482 		}
   483 		report->num_calls++;
   484 		report->total_time += atom_time;
   485 	}
   486 }