diff --git a/source/main.cpp b/source/main.cpp index e4eac0223c..954a7e89e0 100644 --- a/source/main.cpp +++ b/source/main.cpp @@ -259,6 +259,7 @@ static void Frame() // debugging easier. if( !g_NetClient && !g_app_has_focus ) { + PROFILE("non-focus delay"); need_update = false; // don't use SDL_WaitEvent: don't want the main loop to freeze until app focus is restored SDL_Delay(10); @@ -323,12 +324,9 @@ static void Frame() ogl_WarnIfError(); - PROFILE_START( "game logic" ); if (g_Game && g_Game->IsGameStarted() && need_update) { - PROFILE_START( "simulation update" ); g_Game->Update(TimeSinceLastFrame); - PROFILE_END( "simulation update" ); PROFILE_START( "camera update" ); g_Game->GetView()->Update(float(TimeSinceLastFrame)); @@ -353,7 +351,6 @@ static void Frame() if(snd_update(0, 0, 0) < 0) debug_printf(L"snd_update (pos=0 version) failed\n"); } - PROFILE_END( "game logic" ); // Immediately flush any messages produced by simulation code PROFILE_START("network flush"); @@ -363,9 +360,7 @@ static void Frame() g_UserReporter.Update(); - PROFILE_START( "update console" ); g_Console->Update(TimeSinceLastFrame); - PROFILE_END( "update console" ); PROFILE_START("render"); ogl_WarnIfError(); diff --git a/source/network/NetTurnManager.cpp b/source/network/NetTurnManager.cpp index 5ae7095c6c..cc9873ad91 100644 --- a/source/network/NetTurnManager.cpp +++ b/source/network/NetTurnManager.cpp @@ -74,6 +74,19 @@ void CNetTurnManager::SetPlayerID(int playerId) m_PlayerId = playerId; } +bool CNetTurnManager::WillUpdate(float frameLength) +{ + // Keep this in sync with the return value of Update() + + if (m_DeltaTime + frameLength < 0) + return false; + + if (m_ReadyTurn <= m_CurrentTurn) + return false; + + return true; +} + bool CNetTurnManager::Update(float frameLength, size_t maxTurns) { m_DeltaTime += frameLength; diff --git a/source/network/NetTurnManager.h b/source/network/NetTurnManager.h index 3b31cdedf5..16f018b9c1 100644 --- a/source/network/NetTurnManager.h +++ b/source/network/NetTurnManager.h @@ -74,6 +74,12 @@ public: */ bool Update(float frameLength, size_t maxTurns); + /** + * Returns whether Update(frameLength, ...) will process at least one new turn. + * @param frameLength length of the previous frame in seconds + */ + bool WillUpdate(float frameLength); + /** * Advance the graphics by a certain time. * @param frameLength length of the previous frame in seconds diff --git a/source/ps/Game.cpp b/source/ps/Game.cpp index 297625b647..3315e45a32 100644 --- a/source/ps/Game.cpp +++ b/source/ps/Game.cpp @@ -227,16 +227,20 @@ bool CGame::Update(double deltaTime, bool doInterpolate) bool ok = true; if (deltaTime) { + // To avoid confusing the profiler, we need to trigger the new turn + // while we're not nested inside any PROFILE blocks + if (m_TurnManager->WillUpdate(deltaTime)) + g_Profiler.Turn(); + // At the normal sim rate, we currently want to render at least one // frame per simulation turn, so let maxTurns be 1. But for fast-forward // sim rates we want to allow more, so it's not bounded by framerate, // so just use the sim rate itself as the number of turns per frame. size_t maxTurns = (size_t)m_SimRate; - PROFILE("update"); + PROFILE("simulation update"); if (m_TurnManager->Update(deltaTime, maxTurns)) { - g_Profiler.Turn(); g_GUI->SendEventToAll("SimulationUpdate"); GetView()->GetLOSTexture().MakeDirty(); } diff --git a/source/ps/Profile.cpp b/source/ps/Profile.cpp index 76301319a8..21d2ffc39c 100644 --- a/source/ps/Profile.cpp +++ b/source/ps/Profile.cpp @@ -174,6 +174,14 @@ CStr CProfileNodeTable::GetCellText(size_t row, size_t col) unlogged_mallocs_turn -= (*it)->GetTurnMallocs(); } + // The root node can't easily count per-turn values (since Turn isn't called until + // halfway though a frame), so just reset them the zero to prevent weird displays + if (!node->GetParent()) + { + unlogged_time_turn = 0.0; + unlogged_mallocs_turn = 0.0; + } + if (col == 2) sprintf_s(buf, ARRAY_SIZE(buf), "%7.3f", unlogged_time_frame * 1000.0f); else if (col == 3) @@ -596,7 +604,7 @@ void CProfileNode::Call() { calls_frame_current++; calls_turn_current++; - if( recursion++ == 0 ) + if (recursion++ == 0) { start = timer_Time(); start_mallocs = get_memory_alloc_count(); @@ -621,8 +629,6 @@ CProfileManager::CProfileManager() : root(NULL) { StructuralReset(); - frame_start = 0.0; - frame_start_mallocs = 0; } CProfileManager::~CProfileManager() @@ -653,22 +659,19 @@ void CProfileManager::Stop() void CProfileManager::Reset() { root->Reset(); - start = frame_start = timer_Time(); - start_mallocs = frame_start_mallocs = get_memory_alloc_count(); } void CProfileManager::Frame() { ONCE(alloc_hook_initialize()); - - // Fake a return/call to update the root's stats - root->Return(); - root->Call(); + + root->time_frame_current += (timer_Time() - root->start); + root->mallocs_frame_current += (get_memory_alloc_count() - root->start_mallocs); root->Frame(); - - frame_start = timer_Time(); - frame_start_mallocs = get_memory_alloc_count(); + + root->start = timer_Time(); + root->start_mallocs = get_memory_alloc_count(); } void CProfileManager::Turn() diff --git a/source/ps/Profile.h b/source/ps/Profile.h index 9bcad6fb12..a84f21eb8c 100644 --- a/source/ps/Profile.h +++ b/source/ps/Profile.h @@ -111,10 +111,6 @@ class CProfileManager : public Singleton { CProfileNode* root; CProfileNode* current; - double start; - double frame_start; - long start_mallocs; - long frame_start_mallocs; public: CProfileManager(); diff --git a/source/scriptinterface/ScriptInterface.cpp b/source/scriptinterface/ScriptInterface.cpp index 84a5a52ed0..6ee900178d 100644 --- a/source/scriptinterface/ScriptInterface.cpp +++ b/source/scriptinterface/ScriptInterface.cpp @@ -34,6 +34,10 @@ #include #include #include +#include +#include +#include +#include #include "valgrind.h" @@ -93,18 +97,104 @@ private: return closure; } + // To profile scripts usefully, we use a call hook that's called on every enter/exit, + // and need to find the function name. But most functions are anonymous so we make do + // with filename plus line number instead. + // Computing the names is fairly expensive, and we need to return an interned char* + // for the profiler to hold a copy of, so we use boost::flyweight to construct interned + // strings per call location. + + // Identifies a location in a script + struct ScriptLocation + { + JSContext* cx; + JSScript* script; + jsbytecode* pc; + + bool operator==(const ScriptLocation& b) const + { + return cx == b.cx && script == b.script && pc == b.pc; + } + + friend std::size_t hash_value(const ScriptLocation& loc) + { + std::size_t seed = 0; + boost::hash_combine(seed, loc.cx); + boost::hash_combine(seed, loc.script); + boost::hash_combine(seed, loc.pc); + return seed; + } + }; + + // Computes and stores the name of a location in a script + struct ScriptLocationName + { + ScriptLocationName(const ScriptLocation& loc) + { + JSContext* cx = loc.cx; + JSScript* script = loc.script; + jsbytecode* pc = loc.pc; + + std::string filename = JS_GetScriptFilename(cx, script); + size_t slash = filename.rfind('/'); + if (slash != filename.npos) + filename = filename.substr(slash+1); + + uintN line = JS_PCToLineNumber(cx, script, pc); + + std::stringstream ss; + ss << "(" << filename << ":" << line << ")"; + name = ss.str(); + } + + std::string name; + }; + + // Flyweight types (with no_locking because the call hooks are only used in the + // main thread, and no_tracking because we mustn't delete values the profiler is + // using and it's not going to waste much memory) + typedef boost::flyweight< + std::string, + boost::flyweights::no_tracking, + boost::flyweights::no_locking + > StringFlyweight; + typedef boost::flyweight< + boost::flyweights::key_value, + boost::flyweights::no_tracking, + boost::flyweights::no_locking + > LocFlyweight; + static void* jshook_function(JSContext* cx, JSStackFrame* fp, JSBool before, JSBool* UNUSED(ok), void* closure) { - JSFunction* fn = JS_GetFrameFunction(cx, fp); - if (before) + if (!before) { - if (fn) - g_Profiler.StartScript(JS_GetFunctionName(fn)); - else - g_Profiler.StartScript("function invocation"); - } - else g_Profiler.Stop(); + return closure; + } + + JSFunction* fn = JS_GetFrameFunction(cx, fp); + if (!fn) + { + g_Profiler.StartScript("(function)"); + return closure; + } + + // Try to get the name of non-anonymous functions + JSString* name = JS_GetFunctionId(fn); + if (name) + { + char* chars = JS_EncodeString(cx, name); + if (chars) + { + g_Profiler.StartScript(StringFlyweight(chars).get().c_str()); + JS_free(cx, chars); + return closure; + } + } + + // No name - compute from the location instead + ScriptLocation loc = { cx, JS_GetFrameScript(cx, fp), JS_GetFramePC(cx, fp) }; + g_Profiler.StartScript(LocFlyweight(loc).get().name.c_str()); return closure; }