From e8ef74156a4fd105577bbbef0121ccd0b7887899 Mon Sep 17 00:00:00 2001 From: Aleric Inglewood Date: Fri, 8 Mar 2013 01:50:02 +0100 Subject: [PATCH] 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 | 18 ++++++++++++-- indra/aistatemachine/aistatemachine.h | 22 +++++++++++------ indra/llmessage/llurlrequest.cpp | 32 ++++++++++++++++++++++++- indra/llmessage/llurlrequest.h | 6 +++++ 4 files changed, 68 insertions(+), 10 deletions(-) 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.