Added print_statemachine_diagnostics

The responder name is now cached in LLURLRequest
(ResponderBase::getName() must return a string literal).
The run time (in the main thread) per state machine is now accumulated
in AIStateMachine (instead of AIEngine::QueueElement).
When AIStateMachine::mainloop runs longer than StateMachineMaxTime
then a warning is printed that now includes the time spent in the
slowest state machine (that frame) and (if it is a LLURLRequest)
what the corresponding responder is. Also the total accumulated run
time of that state machine is printed.

From this is can be concluded that the only responder currently
regularly holding up the main thread is LLMeshLODResponder (mostly 30 to
100 ms, but with spikes in the 1 to 2 second range some times).

indra/aistatemachine/aistatemachine.cpp

@@ -293,6 +293,8 @@ 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);
+
 // MAIN-THREAD
 void AIEngine::mainloop(void)
 {
@@ -303,6 +305,10 @@ void AIEngine::mainloop(void)
 	queued_element = engine_state_w->list.begin();
   }
   U64 total_clocks = 0;
+#ifndef LL_RELEASE_FOR_DOWNLOAD
+  U64 max_delta = 0;
+  queued_type::value_type slowest_element(NULL);
+#endif
   while (queued_element != end)
   {
 	AIStateMachine& state_machine(queued_element->statemachine());
@@ -312,8 +318,15 @@ void AIEngine::mainloop(void)
 	  state_machine.multiplex(AIStateMachine::normal_run);
 	}
 	U64 delta = get_clock_count() - start;
-	queued_element->add(delta);
+	state_machine.add(delta);
 	total_clocks += delta;
+#ifndef LL_RELEASE_FOR_DOWNLOAD
+	if (delta > max_delta)
+	{
+	  max_delta = delta;
+	  slowest_element = *queued_element;
+	}
+#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)
@@ -328,7 +341,7 @@ void AIEngine::mainloop(void)
 	if (total_clocks >= sMaxCount)
 	{
 #ifndef LL_RELEASE_FOR_DOWNLOAD
-	  llwarns << "AIStateMachine::mainloop did run for " << (total_clocks * 1000 / calc_clock_frequency()) << " ms." << llendl;
+	  print_statemachine_diagnostics(total_clocks, max_delta, slowest_element);
 #endif
 	  Dout(dc::statemachine, "Sorting " << engine_state_w->list.size() << " state machines.");
 	  engine_state_w->list.sort(QueueElementComp());
@@ -909,6 +922,7 @@ void AIStateMachine::reset()
   mDebugSetStatePending = false;
   mDebugRefCalled = false;
 #endif
+  mRuntime = 0;
   bool inside_multiplex;
   {
 	multiplex_state_type_rat state_r(mState);

indra/aistatemachine/aistatemachine.h

@@ -48,20 +48,18 @@ class AIEngine
 	class QueueElement {
 	  private:
 		LLPointer<AIStateMachine> mStateMachine;
-		U64 mRuntime;
 
 	  public:
-		QueueElement(AIStateMachine* statemachine) : mStateMachine(statemachine), mRuntime(0) { }
+		QueueElement(AIStateMachine* statemachine) : mStateMachine(statemachine) { }
 		friend bool operator==(QueueElement const& e1, QueueElement const& e2) { return e1.mStateMachine == e2.mStateMachine; }
 		friend bool operator!=(QueueElement const& e1, QueueElement const& e2) { return e1.mStateMachine != e2.mStateMachine; }
 		friend struct QueueElementComp;
 
 		AIStateMachine const& statemachine(void) const { return *mStateMachine; }
 		AIStateMachine& statemachine(void) { return *mStateMachine; }
-		void add(U64 count) { mRuntime += count; }
 	};
 	struct QueueElementComp {
-	  bool operator()(QueueElement const& e1, QueueElement const& e2) const { return e1.mRuntime < e2.mRuntime; }
+	  inline bool operator()(QueueElement const& e1, QueueElement const& e2) const;
 	};
 
   public:
@@ -194,13 +192,15 @@ class AIStateMachine : public LLThreadSafeRefCount
 	bool mDebugAdvanceStatePending;				// True while advance_state() was called by not handled yet.
 	bool mDebugRefCalled;						// True when ref() is called (or will be called within the critial area of mMultiplexMutex).
 #endif
+	U64 mRuntime;								// Total time spent running in the main thread (in clocks).
 
   public:
-	AIStateMachine(void) : mCallback(NULL), mDefaultEngine(NULL), mYieldEngine(NULL)
+	AIStateMachine(void) : mCallback(NULL), mDefaultEngine(NULL), mYieldEngine(NULL),
 #ifdef SHOW_ASSERT
-		, mDebugLastState(bs_killed), mDebugShouldRun(false), mDebugAborted(false), mDebugContPending(false),
-		  mDebugSetStatePending(false), mDebugAdvanceStatePending(false), mDebugRefCalled(false)
+		mDebugLastState(bs_killed), mDebugShouldRun(false), mDebugAborted(false), mDebugContPending(false),
+		mDebugSetStatePending(false), mDebugAdvanceStatePending(false), mDebugRefCalled(false),
 #endif
+		mRuntime(0)
 	{ }
 
   protected:
@@ -275,6 +275,9 @@ class AIStateMachine : public LLThreadSafeRefCount
 	char const* event_str(event_type event);
 #endif
 
+	void add(U64 count) { mRuntime += count; }
+	U64 getRuntime(void) const { return mRuntime; }
+
   protected:
 	virtual void initialize_impl(void) = 0;
 	virtual void multiplex_impl(state_type run_state) = 0;
@@ -301,6 +304,11 @@ class AIStateMachine : public LLThreadSafeRefCount
 	friend class AIEngine;						// Calls multiplex().
 };
 
+bool AIEngine::QueueElementComp::operator()(QueueElement const& e1, QueueElement const& e2) const
+{
+  return e1.mStateMachine->getRuntime() < e2.mStateMachine->getRuntime();
+}
+
 // This can be used in state_str_impl.
 #define AI_CASE_RETURN(x) do { case x: return #x; } while(0)
 

indra/llmessage/llurlrequest.cpp

@@ -79,7 +79,7 @@ std::string LLURLRequest::actionAsVerb(LLURLRequest::ERequestAction action)
 LLURLRequest::LLURLRequest(LLURLRequest::ERequestAction action, std::string const& url, Injector* body,
 	LLHTTPClient::ResponderPtr responder, AIHTTPHeaders& headers, bool keepalive, bool is_auth, bool no_compression) :
     mAction(action), mURL(url), mKeepAlive(keepalive), mIsAuth(is_auth), mNoCompression(no_compression),
-	mBody(body), mResponder(responder), mHeaders(headers)
+	mBody(body), mResponder(responder), mHeaders(headers), mResponderNameCache(responder ? responder->getName() : "<uninitialized>")
 {
 }
 
@@ -260,3 +260,33 @@ bool LLURLRequest::configure(AICurlEasyRequest_wat const& curlEasyRequest_w)
 	}
 	return rv;
 }
+
+// Called from AIStateMachine::mainloop, but put here because we don't want to include llurlrequest.h there of course.
+void print_statemachine_diagnostics(U64 total_clocks, U64 max_delta, AIEngine::queued_type::const_reference slowest_element)
+{
+  AIStateMachine const& slowest_state_machine = slowest_element.statemachine();
+  LLURLRequest const* request = dynamic_cast<LLURLRequest const*>(&slowest_state_machine);
+  F64 const tfactor = 1000 / calc_clock_frequency();
+  std::ostringstream msg;
+  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 ";
+  if (request)
+  {
+	  msg << "(" << request->getResponderName() << ") ";
+  }
+  msg << "ran for " << (max_delta * tfactor) << " ms";
+  if (slowest_state_machine.getRuntime() > max_delta)
+  {
+	  msg << " (" << (slowest_state_machine.getRuntime() * tfactor) << " ms in total now)";
+  }
+  msg << ".";
+  llwarns << msg.str() << llendl;
+}
+

indra/llmessage/llurlrequest.h

@@ -66,6 +66,11 @@ class LLURLRequest : public AICurlEasyRequestStateMachine {
 	 */
 	LLURLRequest(ERequestAction action, std::string const& url, Injector* body, LLHTTPClient::ResponderPtr responder, AIHTTPHeaders& headers, bool keepalive, bool is_auth, bool no_compression);
 
+	/**
+	 * @brief Cached value of responder->getName() as passed to the constructor.
+	 */
+	char const* getResponderName(void) const { return mResponderNameCache; }
+
   protected:
 	// Call abort(), not delete.
 	/*virtual*/ ~LLURLRequest() { }
@@ -105,6 +110,7 @@ class LLURLRequest : public AICurlEasyRequestStateMachine {
 	U32 mBodySize;
 	LLHTTPClient::ResponderPtr mResponder;
 	AIHTTPHeaders mHeaders;
+	char const* mResponderNameCache;
 
   protected:
 	// Handle initializing the object.