core/Profiler.cpp
author Borja Ferrer <faluco@alliedmods.net>
Fri Jul 04 19:04:33 2008 +0000 (2008-07-04)
changeset 2155 3f1fd7ab3d86
parent 1952 b7aa2b626807
child 2289 44045ead61cd
permissions -rw-r--r--
fixed amb1801, IsFakeClient() wasn't working for TF2 causing false results and crashes
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
}