Make the script profiler more useful, by giving the filename/line for anonymous functions.

Fix the turn-based profiler a bit.

This was SVN commit r8964.

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();

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;

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

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();
 		}

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()

source/ps/Profile.h

@@ -111,10 +111,6 @@ class CProfileManager : public Singleton<CProfileManager>
 {
 	CProfileNode* root;
 	CProfileNode* current;
-	double start;
-	double frame_start;
-	long start_mallocs;
-	long frame_start_mallocs;
 
 public:
 	CProfileManager();

source/scriptinterface/ScriptInterface.cpp

@@ -34,6 +34,10 @@
 #include <boost/preprocessor/repetition/repeat.hpp>
 #include <boost/random/linear_congruential.hpp>
 #include <boost/random/uniform_real.hpp>
+#include <boost/flyweight.hpp>
+#include <boost/flyweight/key_value.hpp>
+#include <boost/flyweight/no_locking.hpp>
+#include <boost/flyweight/no_tracking.hpp>
 
 #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<ScriptLocation, ScriptLocationName>,
+		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;
 	}