diff --git a/indra/aistatemachine/aistatemachine.cpp b/indra/aistatemachine/aistatemachine.cpp index ab4a2ed54..640737e25 100644 --- a/indra/aistatemachine/aistatemachine.cpp +++ b/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); diff --git a/indra/aistatemachine/aistatemachine.h b/indra/aistatemachine/aistatemachine.h index 1af887e96..c374179e1 100644 --- a/indra/aistatemachine/aistatemachine.h +++ b/indra/aistatemachine/aistatemachine.h @@ -48,20 +48,18 @@ class AIEngine class QueueElement { private: LLPointer 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) diff --git a/indra/llmessage/llurlrequest.cpp b/indra/llmessage/llurlrequest.cpp index 18ea5c835..cc7b2c0f6 100644 --- a/indra/llmessage/llurlrequest.cpp +++ b/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() : "") { } @@ -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(&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; +} + diff --git a/indra/llmessage/llurlrequest.h b/indra/llmessage/llurlrequest.h index aa85242db..1f9c09914 100644 --- a/indra/llmessage/llurlrequest.h +++ b/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.