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