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