1.1 --- a/core/Profiler.cpp Fri Jul 11 06:51:21 2008 +0000
1.2 +++ /dev/null Thu Jan 01 00:00:00 1970 +0000
1.3 @@ -1,487 +0,0 @@
1.4 -/**
1.5 - * vim: set ts=4 :
1.6 - * =============================================================================
1.7 - * SourceMod
1.8 - * Copyright (C) 2004-2008 AlliedModders LLC. All rights reserved.
1.9 - * =============================================================================
1.10 - *
1.11 - * This program is free software; you can redistribute it and/or modify it under
1.12 - * the terms of the GNU General Public License, version 3.0, as published by the
1.13 - * Free Software Foundation.
1.14 - *
1.15 - * This program is distributed in the hope that it will be useful, but WITHOUT
1.16 - * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
1.17 - * FOR A PARTICULAR PURPOSE. See the GNU General Public License for more
1.18 - * details.
1.19 - *
1.20 - * You should have received a copy of the GNU General Public License along with
1.21 - * this program. If not, see <http://www.gnu.org/licenses/>.
1.22 - *
1.23 - * As a special exception, AlliedModders LLC gives you permission to link the
1.24 - * code of this program (as well as its derivative works) to "Half-Life 2," the
1.25 - * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software
1.26 - * by the Valve Corporation. You must obey the GNU General Public License in
1.27 - * all respects for all other code used. Additionally, AlliedModders LLC grants
1.28 - * this exception to all derivative works. AlliedModders LLC defines further
1.29 - * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007),
1.30 - * or <http://www.sourcemod.net/license.php>.
1.31 - *
1.32 - * Version: $Id$
1.33 - */
1.34 -
1.35 -#include "Profiler.h"
1.36 -#include "PluginSys.h"
1.37 -#include "sm_stringutil.h"
1.38 -#include "Logger.h"
1.39 -#if defined PLATFORM_POSIX
1.40 -#include <sys/time.h>
1.41 -#include <time.h>
1.42 -#endif
1.43 -
1.44 -ProfileEngine g_Profiler;
1.45 -IProfiler *sm_profiler = &g_Profiler;
1.46 -
1.47 -#if defined PLATFORM_WINDOWS
1.48 -double WINDOWS_PERFORMANCE_FREQUENCY;
1.49 -#endif
1.50 -
1.51 -class EmptyProfiler : public IProfiler
1.52 -{
1.53 -public:
1.54 - void OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
1.55 - {
1.56 - }
1.57 - void OnNativeEnd()
1.58 - {
1.59 - }
1.60 - void OnFunctionBegin(IPluginContext *pContext, const char *name)
1.61 - {
1.62 - }
1.63 - void OnFunctionEnd()
1.64 - {
1.65 - }
1.66 - int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
1.67 - {
1.68 - return 0;
1.69 - }
1.70 - void OnCallbackEnd(int serial)
1.71 - {
1.72 - }
1.73 -} s_EmptyProfiler;
1.74 -
1.75 -inline void InitProfPoint(prof_point_t &pt)
1.76 -{
1.77 -#if defined PLATFORM_WINDOWS
1.78 - QueryPerformanceCounter(&pt.value);
1.79 -#elif defined PLATFORM_POSIX
1.80 - gettimeofday(&pt.value, NULL);
1.81 -#endif
1.82 - pt.is_set = true;
1.83 -}
1.84 -
1.85 -ProfileEngine::ProfileEngine()
1.86 -{
1.87 - m_serial = 0;
1.88 -
1.89 -#if defined PLATFORM_WINDOWS
1.90 - LARGE_INTEGER pf;
1.91 -
1.92 - if (QueryPerformanceFrequency(&pf))
1.93 - {
1.94 - WINDOWS_PERFORMANCE_FREQUENCY = 1.0 / (double)(pf.QuadPart);
1.95 - }
1.96 - else
1.97 - {
1.98 - WINDOWS_PERFORMANCE_FREQUENCY = -1.0;
1.99 - }
1.100 -#endif
1.101 -
1.102 - if (IsEnabled())
1.103 - {
1.104 - InitProfPoint(m_ProfStart);
1.105 - }
1.106 - else
1.107 - {
1.108 - sm_profiler = &s_EmptyProfiler;
1.109 - }
1.110 -}
1.111 -
1.112 -bool ProfileEngine::IsEnabled()
1.113 -{
1.114 -#if defined PLATFORM_WINDOWS
1.115 - return (WINDOWS_PERFORMANCE_FREQUENCY > 0.0);
1.116 -#elif defined PLATFORM_POSIX
1.117 - return true;
1.118 -#endif
1.119 -}
1.120 -
1.121 -inline double DiffProfPoints(const prof_point_t &start, const prof_point_t &end)
1.122 -{
1.123 - double seconds;
1.124 -
1.125 -#if defined PLATFORM_WINDOWS
1.126 - LONGLONG diff;
1.127 -
1.128 - diff = end.value.QuadPart - start.value.QuadPart;
1.129 - seconds = diff * WINDOWS_PERFORMANCE_FREQUENCY;
1.130 -#elif defined PLATFORM_POSIX
1.131 - seconds = (double)(end.value.tv_sec - start.value.tv_sec);
1.132 -
1.133 - if (start.value.tv_usec > end.value.tv_usec)
1.134 - {
1.135 - seconds -= 1.0;
1.136 - seconds += (double)(1000000 - (start.value.tv_usec - end.value.tv_usec)) / 1000000.0;
1.137 - }
1.138 - else
1.139 - {
1.140 - seconds += (double)(end.value.tv_usec - start.value.tv_usec) / 1000000.0;
1.141 - }
1.142 -#endif
1.143 -
1.144 - return seconds;
1.145 -}
1.146 -
1.147 -inline double CalcAtomTime(const prof_atom_t &atom)
1.148 -{
1.149 - if (!atom.end.is_set)
1.150 - {
1.151 - return atom.base_time;
1.152 - }
1.153 -
1.154 - return atom.base_time + DiffProfPoints(atom.start, atom.end);
1.155 -}
1.156 -
1.157 -void ProfileEngine::OnNativeBegin(IPluginContext *pContext, sp_native_t *native)
1.158 -{
1.159 - PushProfileStack(pContext, SP_PROF_NATIVES, native->name);
1.160 -}
1.161 -
1.162 -void ProfileEngine::OnNativeEnd()
1.163 -{
1.164 - assert(!m_AtomStack.empty());
1.165 - assert(m_AtomStack.front().atom_type == SP_PROF_NATIVES);
1.166 -
1.167 - PopProfileStack(&m_Natives);
1.168 -}
1.169 -
1.170 -void ProfileEngine::OnFunctionBegin(IPluginContext *pContext, const char *name)
1.171 -{
1.172 - PushProfileStack(pContext, SP_PROF_FUNCTIONS, name);
1.173 -}
1.174 -
1.175 -void ProfileEngine::OnFunctionEnd()
1.176 -{
1.177 - assert(!m_AtomStack.empty());
1.178 - assert(m_AtomStack.front().atom_type == SP_PROF_FUNCTIONS);
1.179 -
1.180 - PopProfileStack(&m_Functions);
1.181 -}
1.182 -
1.183 -int ProfileEngine::OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc)
1.184 -{
1.185 - PushProfileStack(pContext, SP_PROF_CALLBACKS, pubfunc->name);
1.186 -
1.187 - return m_serial;
1.188 -}
1.189 -
1.190 -void ProfileEngine::OnCallbackEnd(int serial)
1.191 -{
1.192 - assert(!m_AtomStack.empty());
1.193 -
1.194 - /**
1.195 - * Account for the situation where the JIT discards the
1.196 - * stack because there was an RTE of sorts.
1.197 - */
1.198 - if (m_AtomStack.front().atom_type != SP_PROF_CALLBACKS
1.199 - && m_AtomStack.front().atom_serial != serial)
1.200 - {
1.201 - prof_atom_t atom;
1.202 - double total_time;
1.203 -
1.204 - /* There was an error, and we need to discard things. */
1.205 - total_time = 0.0;
1.206 - while (!m_AtomStack.empty()
1.207 - && m_AtomStack.front().atom_type != SP_PROF_CALLBACKS
1.208 - && m_AtomStack.front().atom_serial != serial)
1.209 - {
1.210 - total_time += CalcAtomTime(m_AtomStack.front());
1.211 - m_AtomStack.pop();
1.212 - }
1.213 -
1.214 - /**
1.215 - * Now we can end and discard ourselves, without saving the data.
1.216 - * Since this data is all erroneous anyway, we don't care if it's
1.217 - * not totally accurate.
1.218 - */
1.219 -
1.220 - assert(!m_AtomStack.empty());
1.221 - atom = m_AtomStack.front();
1.222 - m_AtomStack.pop();
1.223 -
1.224 - /* Note: We don't need to resume ourselves because end is set by Pause(). */
1.225 - total_time += CalcAtomTime(atom);
1.226 -
1.227 - ResumeParent(total_time);
1.228 - return;
1.229 - }
1.230 -
1.231 - PopProfileStack(&m_Callbacks);
1.232 -}
1.233 -
1.234 -void ProfileEngine::PushProfileStack(IPluginContext *ctx, int type, const char *name)
1.235 -{
1.236 - prof_atom_t atom;
1.237 -
1.238 - PauseParent();
1.239 -
1.240 - atom.atom_type = type;
1.241 - atom.base_time = 0.0;
1.242 - atom.ctx = ctx->GetContext();
1.243 - atom.name = name;
1.244 - atom.end.is_set = false;
1.245 -
1.246 - if (type == SP_PROF_CALLBACKS)
1.247 - {
1.248 - atom.atom_serial = ++m_serial;
1.249 - }
1.250 - else
1.251 - {
1.252 - atom.atom_serial = 0;
1.253 - }
1.254 -
1.255 - m_AtomStack.push(atom);
1.256 -
1.257 - /* Note: We do this after because the stack could grow and skew results */
1.258 - InitProfPoint(m_AtomStack.front().start);
1.259 -}
1.260 -
1.261 -void ProfileEngine::PopProfileStack(ProfileReport *reporter)
1.262 -{
1.263 - double total_time;
1.264 -
1.265 - prof_atom_t &atom = m_AtomStack.front();
1.266 -
1.267 - /* We're okay to cache our used time. */
1.268 - InitProfPoint(atom.end);
1.269 - total_time = CalcAtomTime(atom);
1.270 -
1.271 - /* Now it's time to save this! This may do a lot of computations which
1.272 - * is why we've cached the time beforehand.
1.273 - */
1.274 - reporter->SaveAtom(atom);
1.275 - m_AtomStack.pop();
1.276 -
1.277 - /* Finally, tell our parent how much time we used. */
1.278 - ResumeParent(total_time);
1.279 -}
1.280 -
1.281 -void ProfileEngine::PauseParent()
1.282 -{
1.283 - if (m_AtomStack.empty())
1.284 - {
1.285 - return;
1.286 - }
1.287 -
1.288 - InitProfPoint(m_AtomStack.front().end);
1.289 -}
1.290 -
1.291 -void ProfileEngine::ResumeParent(double addTime)
1.292 -{
1.293 - if (m_AtomStack.empty())
1.294 - {
1.295 - return;
1.296 - }
1.297 -
1.298 - prof_atom_t &atom = m_AtomStack.front();
1.299 -
1.300 - /* Move its "paused time" to its base (known) time,
1.301 - * then reset the start/end. Note that since CalcAtomTime()
1.302 - * reads the base time, we SHOULD NOT use += to add.
1.303 - */
1.304 - atom.base_time = CalcAtomTime(atom);
1.305 - atom.base_time += addTime;
1.306 - InitProfPoint(atom.start);
1.307 - atom.end.is_set = false;
1.308 -}
1.309 -
1.310 -void ProfileEngine::Clear()
1.311 -{
1.312 - m_Natives.Clear();
1.313 - m_Callbacks.Clear();
1.314 - m_Functions.Clear();
1.315 - InitProfPoint(m_ProfStart);
1.316 -}
1.317 -
1.318 -void ProfileEngine::OnSourceModAllInitialized()
1.319 -{
1.320 - g_RootMenu.AddRootConsoleCommand("profiler", "Profiler commands", this);
1.321 -}
1.322 -
1.323 -void ProfileEngine::OnSourceModShutdown()
1.324 -{
1.325 - g_RootMenu.RemoveRootConsoleCommand("profiler", this);
1.326 -}
1.327 -
1.328 -void ProfileEngine::OnRootConsoleCommand(const char *cmdname, const CCommand &command)
1.329 -{
1.330 - if (command.ArgC() >= 3)
1.331 - {
1.332 - if (strcmp(command.Arg(2), "flush") == 0)
1.333 - {
1.334 - FILE *fp;
1.335 - char path[256];
1.336 -
1.337 - g_SourceMod.BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL));
1.338 -
1.339 - if ((fp = fopen(path, "wt")) == NULL)
1.340 - {
1.341 - g_RootMenu.ConsolePrint("Failed, could not open file for writing: %s", path);
1.342 - return;
1.343 - }
1.344 -
1.345 - GenerateReport(fp);
1.346 -
1.347 - fclose(fp);
1.348 -
1.349 - g_RootMenu.ConsolePrint("Profiler report generated as: %s\n", path);
1.350 -
1.351 - return;
1.352 - }
1.353 - }
1.354 -
1.355 - g_RootMenu.ConsolePrint("Profiler commands:");
1.356 - g_RootMenu.DrawGenericOption("flush", "Flushes statistics to disk and starts over");
1.357 -}
1.358 -
1.359 -bool ProfileEngine::GenerateReport(FILE *fp)
1.360 -{
1.361 - time_t t;
1.362 - double total_time;
1.363 - prof_point_t end_time;
1.364 -
1.365 - InitProfPoint(end_time);
1.366 - total_time = DiffProfPoints(m_ProfStart, end_time);
1.367 -
1.368 - t = time(NULL);
1.369 -
1.370 - fprintf(fp, "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n\n");
1.371 - fprintf(fp, "<profile time=\"%d\" uptime=\"%f\">\n", (int)t, total_time);
1.372 - WriteReport(fp, &m_Natives, "natives");
1.373 - WriteReport(fp, &m_Callbacks, "callbacks");
1.374 - WriteReport(fp, &m_Functions, "functions");
1.375 - fprintf(fp, "</profile>\n");
1.376 -
1.377 - return true;
1.378 -}
1.379 -
1.380 -void ProfileEngine::WriteReport(FILE *fp, ProfileReport *report, const char *name)
1.381 -{
1.382 - size_t i, num;
1.383 - prof_atom_report_t *ar;
1.384 - char new_name[512];
1.385 -
1.386 - fprintf(fp, " <report name=\"%s\">\n", name);
1.387 -
1.388 - num = report->GetNumReports();
1.389 - for (i = 0; i < num; i++)
1.390 - {
1.391 - ar = report->GetReport(i);
1.392 -
1.393 - strncopy(new_name, ar->atom_name, sizeof(new_name));
1.394 - UTIL_ReplaceAll(new_name, sizeof(new_name), "<", "<");
1.395 - UTIL_ReplaceAll(new_name, sizeof(new_name), ">", ">");
1.396 -
1.397 - fprintf(fp, " <item name=\"%s\" numcalls=\"%d\" mintime=\"%f\" maxtime=\"%f\" totaltime=\"%f\"/>\n",
1.398 - new_name,
1.399 - ar->num_calls,
1.400 - ar->min_time,
1.401 - ar->max_time,
1.402 - ar->total_time);
1.403 - }
1.404 -
1.405 - fprintf(fp, " </report>\n");
1.406 -}
1.407 -
1.408 -ProfileReport::~ProfileReport()
1.409 -{
1.410 - for (size_t i = 0; i < m_Reports.size(); i++)
1.411 - {
1.412 - delete m_Reports[i];
1.413 - }
1.414 -}
1.415 -
1.416 -void ProfileReport::Clear()
1.417 -{
1.418 - m_ReportLookup.clear();
1.419 - for (size_t i = 0; i < m_Reports.size(); i++)
1.420 - {
1.421 - delete m_Reports[i];
1.422 - }
1.423 - m_Reports.clear();
1.424 -}
1.425 -
1.426 -size_t ProfileReport::GetNumReports()
1.427 -{
1.428 - return m_Reports.size();
1.429 -}
1.430 -
1.431 -prof_atom_report_t *ProfileReport::GetReport(size_t i)
1.432 -{
1.433 - return m_Reports[i];
1.434 -}
1.435 -
1.436 -void ProfileReport::SaveAtom(const prof_atom_t &atom)
1.437 -{
1.438 - double atom_time;
1.439 - char full_name[256];
1.440 - prof_atom_report_t **pReport, *report;
1.441 -
1.442 - if (atom.atom_type == SP_PROF_NATIVES)
1.443 - {
1.444 - strncopy(full_name, atom.name, sizeof(full_name));
1.445 - }
1.446 - else
1.447 - {
1.448 - CPlugin *pl;
1.449 - const char *file;
1.450 -
1.451 - file = "unknown";
1.452 - if ((pl = g_PluginSys.GetPluginByCtx(atom.ctx)) != NULL)
1.453 - {
1.454 - file = pl->GetFilename();
1.455 - }
1.456 -
1.457 - UTIL_Format(full_name, sizeof(full_name), "%s!%s", file, atom.name);
1.458 - }
1.459 -
1.460 - atom_time = CalcAtomTime(atom);
1.461 -
1.462 - if ((pReport = m_ReportLookup.retrieve(full_name)) == NULL)
1.463 - {
1.464 - report = new prof_atom_report_t;
1.465 -
1.466 - strncopy(report->atom_name, full_name, sizeof(report->atom_name));
1.467 - report->max_time = atom_time;
1.468 - report->min_time = atom_time;
1.469 - report->num_calls = 1;
1.470 - report->total_time = atom_time;
1.471 -
1.472 - m_ReportLookup.insert(full_name, report);
1.473 - m_Reports.push_back(report);
1.474 - }
1.475 - else
1.476 - {
1.477 - report = *pReport;
1.478 -
1.479 - if (atom_time > report->max_time)
1.480 - {
1.481 - report->max_time = atom_time;
1.482 - }
1.483 - if (atom_time < report->min_time)
1.484 - {
1.485 - report->min_time = atom_time;
1.486 - }
1.487 - report->num_calls++;
1.488 - report->total_time += atom_time;
1.489 - }
1.490 -}
