Added more verbose statemachine debug output.

indra/aistatemachine/aistatemachine.cpp

@@ -293,7 +293,36 @@ void AIEngine::add(AIStateMachine* state_machine)
   }
 }
 
-extern void print_statemachine_diagnostics(U64 total_clocks, U64 max_delta, AIEngine::queued_type::const_reference slowest_state_machine);
+#if STATE_MACHINE_PROFILING
+// Called from AIStateMachine::mainloop
+void print_statemachine_diagnostics(U64 total_clocks, AIStateMachine::StateTimerBase::TimeData& slowest_timer, AIEngine::queued_type::const_reference slowest_element)
+{
+	AIStateMachine const& slowest_state_machine = slowest_element.statemachine();
+	F64 const tfactor = 1000 / calc_clock_frequency();
+	std::ostringstream msg;
+
+	U64 max_delta = slowest_timer.GetDuration();
+
+	if (total_clocks > max_delta)
+	{
+		msg << "AIStateMachine::mainloop did run for " << (total_clocks * tfactor) << " ms. The slowest ";
+	}
+	else
+	{
+		msg << "AIStateMachine::mainloop: A ";
+	}
+	msg << "state machine " << "(" << slowest_state_machine.getName() << ") " << "ran for " << (max_delta * tfactor) << " ms";
+	if (slowest_state_machine.getRuntime() > max_delta)
+	{
+		msg << " (" << (slowest_state_machine.getRuntime() * tfactor) << " ms in total now)";
+	}
+	msg << ".\n";
+
+	AIStateMachine::StateTimerBase::DumpTimers(msg);
+
+	llwarns << msg.str() << llendl;
+}
+#endif
 
 // MAIN-THREAD
 void AIEngine::mainloop(void)
@@ -305,28 +334,33 @@ void AIEngine::mainloop(void)
 	queued_element = engine_state_w->list.begin();
   }
   U64 total_clocks = 0;
-#ifndef LL_RELEASE_FOR_DOWNLOAD
-  U64 max_delta = 0;
+#if STATE_MACHINE_PROFILING
   queued_type::value_type slowest_element(NULL);
+  AIStateMachine::StateTimerRoot::TimeData slowest_timer;
 #endif
   while (queued_element != end)
   {
 	AIStateMachine& state_machine(queued_element->statemachine());
-	U64 start = get_clock_count();
-	if (!state_machine.sleep(start))
+	AIStateMachine::StateTimerBase::TimeData time_data;
+	if (!state_machine.sleep(get_clock_count()))
 	{
-	  state_machine.multiplex(AIStateMachine::normal_run);
+		AIStateMachine::StateTimerRoot timer(state_machine.getName());
+		state_machine.multiplex(AIStateMachine::normal_run);
+		time_data = timer.GetTimerData();
 	}
-	U64 delta = get_clock_count() - start;
-	state_machine.add(delta);
-	total_clocks += delta;
-#ifndef LL_RELEASE_FOR_DOWNLOAD
-	if (delta > max_delta)
+	if (U64 delta = time_data.GetDuration())
 	{
-	  max_delta = delta;
-	  slowest_element = *queued_element;
-	}
+		state_machine.add(delta);
+		total_clocks += delta;
+#if STATE_MACHINE_PROFILING
+		if (delta > slowest_timer.GetDuration())
+		{
+			slowest_element = *queued_element;
+			slowest_timer = time_data;
+		}
 #endif
+	}
+
 	bool active = state_machine.active(this);		// This locks mState shortly, so it must be called before locking mEngineState because add() locks mEngineState while holding mState.
 	engine_state_type_wat engine_state_w(mEngineState);
 	if (!active)
@@ -340,8 +374,8 @@ void AIEngine::mainloop(void)
 	}
 	if (total_clocks >= sMaxCount)
 	{
-#ifndef LL_RELEASE_FOR_DOWNLOAD
-	  print_statemachine_diagnostics(total_clocks, max_delta, slowest_element);
+#if STATE_MACHINE_PROFILING
+		print_statemachine_diagnostics(total_clocks, slowest_timer, slowest_element);
 #endif
 	  Dout(dc::statemachine, "Sorting " << engine_state_w->list.size() << " state machines.");
 	  engine_state_w->list.sort(QueueElementComp());
@@ -752,6 +786,22 @@ void AIStateMachine::multiplex(event_type event)
   }
 }
 
+#if STATE_MACHINE_PROFILING
+std::vector<AIStateMachine::StateTimerBase*> AIStateMachine::StateTimerBase::mTimerStack;
+AIStateMachine::StateTimerBase::TimeData AIStateMachine::StateTimerBase::TimeData::sRoot("");
+void AIStateMachine::StateTimer::TimeData::DumpTimer(std::ostringstream& msg, std::string prefix)
+{
+	F64 const tfactor = 1000 / calc_clock_frequency();
+	msg << prefix << mName << " " << (mEnd - mStart)*tfactor << "ms" << std::endl;
+	prefix.push_back(' ');
+	std::vector<TimeData>::iterator it;
+	for (it = mChildren.begin(); it != mChildren.end(); ++it)
+	{
+		it->DumpTimer(msg, prefix);
+	}
+}
+#endif
+
 AIStateMachine::state_type AIStateMachine::begin_loop(base_state_type base_state)
 {
   DoutEntering(dc::statemachine(mSMDebug), "AIStateMachine::begin_loop(" << state_str(base_state) << ") [" << (void*)this << "]");

indra/aistatemachine/aistatemachine.h

@@ -36,6 +36,7 @@
 
 #include "aithreadsafe.h"
 #include <llpointer.h>
+#include "lltimer.h"
 #include <list>
 #include <boost/signals2.hpp>
 
@@ -98,11 +99,140 @@ class AIEngine
 extern AIEngine gMainThreadEngine;
 extern AIEngine gStateMachineThreadEngine;
 
+#ifndef STATE_MACHINE_PROFILING
+#define STATE_MACHINE_PROFILING (LL_RELEASE_FOR_DOWNLOAD)
+#endif
+
 class AIStateMachine : public LLThreadSafeRefCount
 {
   public:
 	typedef U32 state_type;		//!< The type of run_state
 
+	// A simple timer class that will calculate time delta between ctor and GetTimerData call.
+	// Time data is stored as a nested TimeData object.
+	// If STATE_MACHINE_PROFILING is defined then a stack of all StateTimers from root is maintained for debug output.
+	class StateTimerBase
+	{
+	public:
+		class TimeData
+		{
+			friend class StateTimerBase;
+		public:
+			TimeData() : mStart(-1), mEnd(-1) {}
+			U64 GetDuration() {	return mEnd - mStart; }
+		private:
+			U64 mStart, mEnd;
+
+#if !STATE_MACHINE_PROFILING
+			TimeData(const std::string& name) : mStart(get_clock_count()), mEnd(get_clock_count()) {}
+#else
+			TimeData(const std::string& name) : mName(name), mStart(get_clock_count()), mEnd(get_clock_count()) {}
+			void DumpTimer(std::ostringstream& msg, std::string prefix);
+			std::vector<TimeData> mChildren;
+			std::string mName;	
+			static TimeData sRoot;
+#endif
+		};
+	protected:
+#if !STATE_MACHINE_PROFILING
+		StateTimerBase(const std::string& name) : mData(name) {}
+		~StateTimerBase() {}
+		TimeData mData;
+		// Return a copy of the underlying timer data.
+		// This allows the data live beyond the scope of the state timer.
+	public:
+		const TimeData GetTimerData()
+		{
+			mData.mEnd = get_clock_count();	//set mEnd to current time, since GetTimerData() will always be called before the dtor, obv.
+			return mData;
+		}
+#else
+		// Ctors/dtors are hidden. Only StateTimerRoot and StateTimer are permitted to access them.
+		StateTimerBase() : mData(NULL) {}
+		~StateTimerBase()
+		{
+			// If mData is null then the timer was not registered due to being in the wrong thread or the root timer wasn't in the expected state.
+			if (!mData)
+				return;
+			mData->mEnd = get_clock_count();
+			mTimerStack.pop_back();
+		}
+
+		// Also hide internals from everything except StateTimerRoot and StateTimer
+		bool AddAsRoot(const std::string& name)
+		{
+			
+			if (!is_main_thread())
+				return true;	//Ignoring this timer, but pretending it was added.
+			if (!mTimerStack.empty())
+				return false;
+			TimeData::sRoot = TimeData(name);
+			mData = &TimeData::sRoot;
+			mData->mChildren.clear();	
+			mTimerStack.push_back(this);
+			return true;
+		}
+		bool AddAsChild(const std::string& name)
+		{
+			if (!is_main_thread())
+				return true;	//Ignoring this timer, but pretending it was added.
+			if (mTimerStack.empty())
+				return false;
+			mTimerStack.back()->mData->mChildren.push_back(TimeData(name));
+			mData = &mTimerStack.back()->mData->mChildren.back();
+			mTimerStack.push_back(this);
+			return true;
+		}
+
+		TimeData* mData;
+		static std::vector<StateTimerBase*> mTimerStack;
+
+	public:
+		// Debug spew
+		static void DumpTimers(std::ostringstream& msg)
+		{
+			TimeData::sRoot.DumpTimer(msg, "");
+		}
+
+		// Return a copy of the underlying timer data.
+		// This allows the data live beyond the scope of the state timer.
+		const TimeData GetTimerData() const
+		{
+			if (mData)
+			{
+				TimeData ret = *mData;
+				ret.mEnd = get_clock_count();	//set mEnd to current time, since GetTimerData() will always be called before the dtor, obv.
+				return ret;
+			}
+			return TimeData();
+		}
+#endif
+	};
+public:
+#if !STATE_MACHINE_PROFILING
+	typedef StateTimerBase StateTimerRoot;
+	typedef StateTimerBase StateTimer;
+#else
+	class StateTimerRoot : public StateTimerBase
+	{ //A StateTimerRoot can become a child if a root already exists.
+	public:
+		StateTimerRoot(const std::string& name)
+		{
+			if(!AddAsRoot(name))
+				AddAsChild(name);	
+		}
+	};
+	class StateTimer : public StateTimerBase
+	{ //A StateTimer can never become a root
+	public:
+		StateTimer(const std::string& name)
+		{
+			AddAsChild(name);
+		}
+	};
+#endif
+
+
   protected:
 	// The type of event that causes multiplex() to be called.
 	enum event_type {
@@ -302,6 +432,9 @@ class AIStateMachine : public LLThreadSafeRefCount
 	void add(U64 count) { mRuntime += count; }
 	U64 getRuntime(void) const { return mRuntime; }
 
+	// For diagnostics. Every derived class must override this.
+	virtual const char* getName() const = 0;
+
   protected:
 	virtual void initialize_impl(void) = 0;
 	virtual void multiplex_impl(state_type run_state) = 0;

indra/aistatemachine/aistatemachinethread.h

@@ -232,6 +232,13 @@ class AIStateMachineThread : public AIStateMachineThreadBase {
 	// Accessor.
 	THREAD_IMPL& thread_impl(void) { return mThreadImpl; }
 
+	/*virtual*/ const char* getName() const
+	{
+#define STRIZE(arg) #arg
+		return "AIStateMachineThread<"STRIZE(THREAD_IMPL)">";
+#undef STRIZE
+	}
+
   protected:
 	/*virtual*/ AIThreadImpl& impl(void) { return mThreadImpl; }
 };

indra/aistatemachine/aitimer.h

@@ -98,6 +98,8 @@ class AITimer : public AIStateMachine {
 	 */
 	F64 getInterval(void) const { return mInterval; }
 
+	/*virtual*/ const char* getName() const { return "AITimer"; }
+
   protected:
 	// Call finish() (or abort()), not delete.
 	/*virtual*/ ~AITimer() { DoutEntering(dc::statemachine(mSMDebug), "~AITimer() [" << (void*)this << "]"); mFrameTimer.cancel(); }