/** * vim: set ts=4 sw=4 tw=99 noet : * ============================================================================= * SourceMod * Copyright (C) 2004-2008 AlliedModders LLC. All rights reserved. * ============================================================================= * * This program is free software; you can redistribute it and/or modify it under * the terms of the GNU General Public License, version 3.0, as published by the * Free Software Foundation. * * This program is distributed in the hope that it will be useful, but WITHOUT * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS * FOR A PARTICULAR PURPOSE. See the GNU General Public License for more * details. * * You should have received a copy of the GNU General Public License along with * this program. If not, see . * * As a special exception, AlliedModders LLC gives you permission to link the * code of this program (as well as its derivative works) to "Half-Life 2," the * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software * by the Valve Corporation. You must obey the GNU General Public License in * all respects for all other code used. Additionally, AlliedModders LLC grants * this exception to all derivative works. AlliedModders LLC defines further * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007), * or . * * Version: $Id$ */ #include "Profiler.h" #include #if defined PLATFORM_POSIX #include #include #endif #include #include "stringutil.h" ProfileEngine g_Profiler; IProfiler *sm_profiler = &g_Profiler; #if defined PLATFORM_WINDOWS double WINDOWS_PERFORMANCE_FREQUENCY; #endif class EmptyProfiler : public IProfiler { public: void OnNativeBegin(IPluginContext *pContext, sp_native_t *native) { } void OnNativeEnd() { } void OnFunctionBegin(IPluginContext *pContext, const char *name) { } void OnFunctionEnd() { } int OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc) { return 0; } void OnCallbackEnd(int serial) { } } s_EmptyProfiler; inline void InitProfPoint(prof_point_t &pt) { #if defined PLATFORM_WINDOWS QueryPerformanceCounter(&pt.value); #elif defined PLATFORM_POSIX gettimeofday(&pt.value, NULL); #endif pt.is_set = true; } ProfileEngine::ProfileEngine() { m_serial = 0; #if defined PLATFORM_WINDOWS LARGE_INTEGER pf; if (QueryPerformanceFrequency(&pf)) { WINDOWS_PERFORMANCE_FREQUENCY = 1.0 / (double)(pf.QuadPart); } else { WINDOWS_PERFORMANCE_FREQUENCY = -1.0; } #endif if (IsEnabled()) { InitProfPoint(m_ProfStart); } else { sm_profiler = &s_EmptyProfiler; } } bool ProfileEngine::IsEnabled() { #if defined PLATFORM_WINDOWS return (WINDOWS_PERFORMANCE_FREQUENCY > 0.0); #elif defined PLATFORM_POSIX return true; #endif } inline double DiffProfPoints(const prof_point_t &start, const prof_point_t &end) { double seconds; #if defined PLATFORM_WINDOWS LONGLONG diff; diff = end.value.QuadPart - start.value.QuadPart; seconds = diff * WINDOWS_PERFORMANCE_FREQUENCY; #elif defined PLATFORM_POSIX seconds = (double)(end.value.tv_sec - start.value.tv_sec); if (start.value.tv_usec > end.value.tv_usec) { seconds -= 1.0; seconds += (double)(1000000 - (start.value.tv_usec - end.value.tv_usec)) / 1000000.0; } else { seconds += (double)(end.value.tv_usec - start.value.tv_usec) / 1000000.0; } #endif return seconds; } inline double CalcAtomTime(const prof_atom_t &atom) { if (!atom.end.is_set) { return atom.base_time; } return atom.base_time + DiffProfPoints(atom.start, atom.end); } void ProfileEngine::OnNativeBegin(IPluginContext *pContext, sp_native_t *native) { PushProfileStack(pContext, SP_PROF_NATIVES, native->name); } void ProfileEngine::OnNativeEnd() { assert(!m_AtomStack.empty()); assert(m_AtomStack.front().atom_type == SP_PROF_NATIVES); PopProfileStack(&m_Natives); } void ProfileEngine::OnFunctionBegin(IPluginContext *pContext, const char *name) { PushProfileStack(pContext, SP_PROF_FUNCTIONS, name); } void ProfileEngine::OnFunctionEnd() { assert(!m_AtomStack.empty()); assert(m_AtomStack.front().atom_type == SP_PROF_FUNCTIONS); PopProfileStack(&m_Functions); } int ProfileEngine::OnCallbackBegin(IPluginContext *pContext, sp_public_t *pubfunc) { PushProfileStack(pContext, SP_PROF_CALLBACKS, pubfunc->name); return m_serial; } void ProfileEngine::OnCallbackEnd(int serial) { assert(!m_AtomStack.empty()); /** * Account for the situation where the JIT discards the * stack because there was an RTE of sorts. */ if (m_AtomStack.front().atom_type != SP_PROF_CALLBACKS && m_AtomStack.front().atom_serial != serial) { prof_atom_t atom; double total_time; /* There was an error, and we need to discard things. */ total_time = 0.0; while (!m_AtomStack.empty() && m_AtomStack.front().atom_type != SP_PROF_CALLBACKS && m_AtomStack.front().atom_serial != serial) { total_time += CalcAtomTime(m_AtomStack.front()); m_AtomStack.pop(); } /** * Now we can end and discard ourselves, without saving the data. * Since this data is all erroneous anyway, we don't care if it's * not totally accurate. */ assert(!m_AtomStack.empty()); atom = m_AtomStack.front(); m_AtomStack.pop(); /* Note: We don't need to resume ourselves because end is set by Pause(). */ total_time += CalcAtomTime(atom); ResumeParent(total_time); return; } PopProfileStack(&m_Callbacks); } void ProfileEngine::PushProfileStack(IPluginContext *ctx, int type, const char *name) { prof_atom_t atom; PauseParent(); atom.atom_type = type; atom.base_time = 0.0; atom.ctx = ctx->GetContext(); atom.name = name; atom.end.is_set = false; if (type == SP_PROF_CALLBACKS) { atom.atom_serial = ++m_serial; } else { atom.atom_serial = 0; } m_AtomStack.push(atom); /* Note: We do this after because the stack could grow and skew results */ InitProfPoint(m_AtomStack.front().start); } void ProfileEngine::PopProfileStack(ProfileReport *reporter) { double total_time; prof_atom_t &atom = m_AtomStack.front(); /* We're okay to cache our used time. */ InitProfPoint(atom.end); total_time = CalcAtomTime(atom); /* Now it's time to save this! This may do a lot of computations which * is why we've cached the time beforehand. */ reporter->SaveAtom(atom); m_AtomStack.pop(); /* Finally, tell our parent how much time we used. */ ResumeParent(total_time); } void ProfileEngine::PauseParent() { if (m_AtomStack.empty()) { return; } InitProfPoint(m_AtomStack.front().end); } void ProfileEngine::ResumeParent(double addTime) { if (m_AtomStack.empty()) { return; } prof_atom_t &atom = m_AtomStack.front(); /* Move its "paused time" to its base (known) time, * then reset the start/end. Note that since CalcAtomTime() * reads the base time, we SHOULD NOT use += to add. */ atom.base_time = CalcAtomTime(atom); atom.base_time += addTime; InitProfPoint(atom.start); atom.end.is_set = false; } void ProfileEngine::Clear() { m_Natives.Clear(); m_Callbacks.Clear(); m_Functions.Clear(); InitProfPoint(m_ProfStart); } void ProfileEngine::OnSourceModAllInitialized() { rootmenu->AddRootConsoleCommand2("profiler", "Profiler commands", this); } void ProfileEngine::OnSourceModShutdown() { rootmenu->RemoveRootConsoleCommand("profiler", this); } void ProfileEngine::OnRootConsoleCommand2(const char *cmdname, const ICommandArgs *command) { if (command->ArgC() >= 3) { if (strcmp(command->Arg(2), "flush") == 0) { FILE *fp; char path[256]; g_pSM->BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL)); if ((fp = fopen(path, "wt")) == NULL) { rootmenu->ConsolePrint("Failed, could not open file for writing: %s", path); return; } GenerateReport(fp); fclose(fp); Clear(); rootmenu->ConsolePrint("Profiler report generated as: %s\n", path); return; } else if (strcmp(command->Arg(2), "report") == 0) { FILE *fp; char path[256]; g_pSM->BuildPath(Path_SM, path, sizeof(path), "logs/profile_%d.xml", (int)time(NULL)); if ((fp = fopen(path, "wt")) == NULL) { rootmenu->ConsolePrint("Failed, could not open file for writing: %s", path); return; } GenerateReport(fp); fclose(fp); rootmenu->ConsolePrint("Profiler report generated as: %s\n", path); return; } else if (strcmp(command->Arg(2), "clear") == 0) { Clear(); rootmenu->ConsolePrint("Profiler statistics cleared.\n"); return; } } rootmenu->ConsolePrint("Profiler commands:"); rootmenu->DrawGenericOption("flush", "Flushes statistics to disk and starts over"); rootmenu->DrawGenericOption("report", "Flushes statistics to disk"); rootmenu->DrawGenericOption("clear", "Clears statistics"); } bool ProfileEngine::GenerateReport(FILE *fp) { time_t t; double total_time; prof_point_t end_time; InitProfPoint(end_time); total_time = DiffProfPoints(m_ProfStart, end_time); t = time(NULL); fprintf(fp, "\n\n"); fprintf(fp, "\n", (int)t, total_time); WriteReport(fp, &m_Natives, "natives"); WriteReport(fp, &m_Callbacks, "callbacks"); WriteReport(fp, &m_Functions, "functions"); fprintf(fp, "\n"); return true; } void ProfileEngine::WriteReport(FILE *fp, ProfileReport *report, const char *name) { size_t i, num; prof_atom_report_t *ar; char new_name[512]; fprintf(fp, " \n", name); num = report->GetNumReports(); for (i = 0; i < num; i++) { ar = report->GetReport(i); strncopy(new_name, ar->atom_name, sizeof(new_name)); UTIL_ReplaceAll(new_name, sizeof(new_name), "<", "<", true); UTIL_ReplaceAll(new_name, sizeof(new_name), ">", ">", true); fprintf(fp, " \n", new_name, ar->num_calls, ar->min_time, ar->max_time, ar->total_time); } fprintf(fp, " \n"); } ProfileReport::~ProfileReport() { for (size_t i = 0; i < m_Reports.size(); i++) { delete m_Reports[i]; } } void ProfileReport::Clear() { m_ReportLookup.clear(); for (size_t i = 0; i < m_Reports.size(); i++) { delete m_Reports[i]; } m_Reports.clear(); } size_t ProfileReport::GetNumReports() { return m_Reports.size(); } prof_atom_report_t *ProfileReport::GetReport(size_t i) { return m_Reports[i]; } void ProfileReport::SaveAtom(const prof_atom_t &atom) { double atom_time; char full_name[256]; prof_atom_report_t *report; if (atom.atom_type == SP_PROF_NATIVES) { smcore.strncopy(full_name, atom.name, sizeof(full_name)); } else { IPlugin *pl; const char *file; file = "unknown"; if ((pl = pluginsys->FindPluginByContext(atom.ctx)) != NULL) { file = pl->GetFilename(); } smcore.Format(full_name, sizeof(full_name), "%s!%s", file, atom.name); } atom_time = CalcAtomTime(atom); if (!m_ReportLookup.retrieve(full_name, &report)) { report = new prof_atom_report_t; smcore.strncopy(report->atom_name, full_name, sizeof(report->atom_name)); report->max_time = atom_time; report->min_time = atom_time; report->num_calls = 1; report->total_time = atom_time; m_ReportLookup.insert(full_name, report); m_Reports.push_back(report); } else { if (atom_time > report->max_time) { report->max_time = atom_time; } if (atom_time < report->min_time) { report->min_time = atom_time; } report->num_calls++; report->total_time += atom_time; } }