From 62fcbb063a191fa4789145c3937e7bef6ce544bd Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 5 Sep 2012 18:49:28 -0700 Subject: SH-3275 WIP Run viewer metrics for object update messages first pass at LLTrace framework --- indra/llcommon/llfasttimer.cpp | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 6970c29092..939e332c3b 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -216,7 +216,7 @@ LLFastTimer::NamedTimer::NamedTimer(const std::string& name) : mName(name), mCollapsed(true), mParent(NULL), - mTotalTimeCounter(0), + mTreeTimeCounter(0), mCountAverage(0), mCallAverage(0), mNeedsSorting(false), @@ -389,6 +389,8 @@ void LLFastTimer::NamedTimer::accumulateTimings() U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; cur_timer->mFrameState->mSelfTimeCounter += self_time_delta; + cur_timer->mFrameState->mTotalTimeCounter += cumulative_time_delta; + cur_timer->mStartTime = cur_time; cur_data = &cur_timer->mLastTimerData; @@ -403,10 +405,10 @@ void LLFastTimer::NamedTimer::accumulateTimings() ++it) { NamedTimer* timerp = (*it); - timerp->mTotalTimeCounter = timerp->getFrameState().mSelfTimeCounter; + timerp->mTreeTimeCounter = timerp->getFrameState().mSelfTimeCounter; for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) { - timerp->mTotalTimeCounter += (*child_it)->mTotalTimeCounter; + timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; } S32 cur_frame = sCurFrameIndex; @@ -415,8 +417,8 @@ void LLFastTimer::NamedTimer::accumulateTimings() // update timer history int hidx = cur_frame % HISTORY_NUM; - timerp->mCountHistory[hidx] = timerp->mTotalTimeCounter; - timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTotalTimeCounter) / (cur_frame+1); + timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; + timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); timerp->mCallHistory[hidx] = timerp->getFrameState().mCalls; timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->getFrameState().mCalls) / (cur_frame+1); } -- cgit v1.2.3 From 6814906fec95aeb90dbc99605f74f241a72af12b Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 5 Sep 2012 18:54:26 -0700 Subject: SH-3275 WIP Run viewer metrics for object update messages build fix --- indra/llcommon/llfasttimer.cpp | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 939e332c3b..0abaf73063 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -388,8 +388,8 @@ void LLFastTimer::NamedTimer::accumulateTimings() U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; - cur_timer->mFrameState->mSelfTimeCounter += self_time_delta; - cur_timer->mFrameState->mTotalTimeCounter += cumulative_time_delta; + cur_data->mFrameState->mSelfTimeCounter += self_time_delta; + cur_data->mFrameState->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; @@ -643,16 +643,16 @@ const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& na return NamedTimerFactory::instance().getTimerByName(name); } -LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) -: mFrameState(state) -{ - U32 start_time = getCPUClockCount32(); - mStartTime = start_time; - mFrameState->mActiveCount++; - LLFastTimer::sCurTimerData.mCurTimer = this; - LLFastTimer::sCurTimerData.mFrameState = mFrameState; - LLFastTimer::sCurTimerData.mChildTime = 0; - mLastTimerData = LLFastTimer::sCurTimerData; -} +//LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) +//: mFrameState(state) +//{ +// U32 start_time = getCPUClockCount32(); +// mStartTime = start_time; +// mFrameState->mActiveCount++; +// LLFastTimer::sCurTimerData.mCurTimer = this; +// LLFastTimer::sCurTimerData.mFrameState = mFrameState; +// LLFastTimer::sCurTimerData.mChildTime = 0; +// mLastTimerData = LLFastTimer::sCurTimerData; +//} -- cgit v1.2.3 From 860ff2f7e2a7fe932dfb7c148f0dbc0067018038 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 7 Nov 2012 00:38:21 -0800 Subject: SH-3499 WIP Ensure asset stats output is correct fixed trace data gathering and routing from background thread simplified slave->master thread communication (eliminated redundant recording and proxy object) improved performance of fast timer data gathering (slow iterators) --- indra/llcommon/llfasttimer.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 0abaf73063..4f67004773 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -319,7 +319,7 @@ void LLFastTimer::NamedTimer::buildHierarchy() // set up initial tree { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { NamedTimer& timer = *it; if (&timer == NamedTimerFactory::instance().getRootTimer()) continue; @@ -449,7 +449,7 @@ void LLFastTimer::NamedTimer::resetFrame() LLSD sd; { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { NamedTimer& timer = *it; FrameState& info = timer.getFrameState(); @@ -472,7 +472,7 @@ void LLFastTimer::NamedTimer::resetFrame() } // reset for next frame - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { NamedTimer& timer = *it; @@ -512,7 +512,7 @@ void LLFastTimer::NamedTimer::reset() // reset all history { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { NamedTimer& timer = *it; if (&timer != NamedTimerFactory::instance().getRootTimer()) -- cgit v1.2.3 From a3e3e8b4ccd96e98da73acf1c584bbfa5a8b2b56 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 12 Nov 2012 19:08:14 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system simplified llfasttimer code down to 2 classes llunit unit conversion now done in floating point or 64 bit integer precision, depending on source type --- indra/llcommon/llfasttimer.cpp | 270 +++++++++++++---------------------------- 1 file changed, 85 insertions(+), 185 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 4f67004773..c4839fed77 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -32,6 +32,7 @@ #include "llsingleton.h" #include "lltreeiterators.h" #include "llsdserialize.h" +#include "llunit.h" #include @@ -73,13 +74,13 @@ U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution // FIXME: move these declarations to the relevant modules // helper functions -typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; +typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; -static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::NamedTimer& id) +static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::DeclareTimer& id) { return timer_tree_bottom_up_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::endChildren), _1)); } static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() @@ -87,14 +88,14 @@ static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() return timer_tree_bottom_up_iterator_t(); } -typedef LLTreeDFSIter timer_tree_dfs_iterator_t; +typedef LLTreeDFSIter timer_tree_dfs_iterator_t; -static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::NamedTimer& id) +static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::DeclareTimer& id) { return timer_tree_dfs_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::endChildren), _1)); } static timer_tree_dfs_iterator_t end_timer_tree() @@ -102,75 +103,12 @@ static timer_tree_dfs_iterator_t end_timer_tree() return timer_tree_dfs_iterator_t(); } -// factory class that creates NamedTimers via static DeclareTimer objects -class NamedTimerFactory : public LLSingleton +LLFastTimer::DeclareTimer& LLFastTimer::DeclareTimer::getRootTimer() { -public: - NamedTimerFactory() - : mTimerRoot(NULL) - {} - - /*virtual */ void initSingleton() - { - mTimerRoot = new LLFastTimer::NamedTimer("root"); - mRootFrameState.setNamedTimer(mTimerRoot); - mTimerRoot->setFrameState(&mRootFrameState); - mTimerRoot->mParent = mTimerRoot; - mTimerRoot->setCollapsed(false); - mRootFrameState.mParent = &mRootFrameState; - } - - ~NamedTimerFactory() - { - std::for_each(mTimers.begin(), mTimers.end(), DeletePairedPointer()); - - delete mTimerRoot; - } - - LLFastTimer::NamedTimer& createNamedTimer(const std::string& name, LLFastTimer::FrameState* state) - { - LLFastTimer::NamedTimer* timer = new LLFastTimer::NamedTimer(name); - timer->setFrameState(state); - timer->setParent(mTimerRoot); - mTimers.insert(std::make_pair(name, timer)); - - return *timer; - } - - LLFastTimer::NamedTimer* getTimerByName(const std::string& name) - { - timer_map_t::iterator found_it = mTimers.find(name); - if (found_it != mTimers.end()) - { - return found_it->second; - } - return NULL; - } - - LLFastTimer::NamedTimer* getRootTimer() { return mTimerRoot; } - - typedef std::multimap timer_map_t; - timer_map_t::iterator beginTimers() { return mTimers.begin(); } - timer_map_t::iterator endTimers() { return mTimers.end(); } - S32 timerCount() { return mTimers.size(); } - -private: - timer_map_t mTimers; - - LLFastTimer::NamedTimer* mTimerRoot; - LLFastTimer::FrameState mRootFrameState; -}; - -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open ) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) -{ - mTimer.setCollapsed(!open); + static DeclareTimer root_timer("root", true, NULL); + return root_timer; } -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) -{ -} //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) @@ -183,7 +121,7 @@ U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz - static U64 sCPUClockFrequency = U64(LLProcessorInfo().getCPUFrequency()*1000000.0); + static LLUnit sCPUClockFrequency = LLProcessorInfo().getCPUFrequency(); // we drop the low-order byte in our timers, so report a lower frequency #else @@ -206,49 +144,44 @@ LLFastTimer::FrameState::FrameState() : mActiveCount(0), mCalls(0), mSelfTimeCounter(0), - mParent(NULL), mLastCaller(NULL), mMoveUpTree(false) {} -LLFastTimer::NamedTimer::NamedTimer(const std::string& name) +LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open, DeclareTimer* parent) : mName(name), mCollapsed(true), mParent(NULL), mTreeTimeCounter(0), mCountAverage(0), mCallAverage(0), - mNeedsSorting(false), - mFrameState(NULL) + mNeedsSorting(false) { + setCollapsed(!open); + + if (parent) + { + setParent(parent); + } + else + { + mParent = this; + } + mCountHistory = new U32[HISTORY_NUM]; memset(mCountHistory, 0, sizeof(U32) * HISTORY_NUM); mCallHistory = new U32[HISTORY_NUM]; memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); } -LLFastTimer::NamedTimer::~NamedTimer() +LLFastTimer::DeclareTimer::~DeclareTimer() { delete[] mCountHistory; delete[] mCallHistory; } -std::string LLFastTimer::NamedTimer::getToolTip(S32 history_idx) -{ - F64 ms_multiplier = 1000.0 / (F64)LLFastTimer::countsPerSecond(); - if (history_idx < 0) - { - // by default, show average number of call - return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getCountAverage() * ms_multiplier), (S32)getCallAverage()); - } - else - { - return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getHistoricalCount(history_idx) * ms_multiplier), (S32)getHistoricalCalls(history_idx)); - } -} - -void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) +void LLFastTimer::DeclareTimer::setParent(DeclareTimer* parent) { llassert_always(parent != this); llassert_always(parent != NULL); @@ -264,8 +197,8 @@ void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) // subtract average timing from previous parent mParent->mCountAverage -= mCountAverage; - std::vector& children = mParent->getChildren(); - std::vector::iterator found_it = std::find(children.begin(), children.end(), this); + std::vector& children = mParent->getChildren(); + std::vector::iterator found_it = std::find(children.begin(), children.end(), this); if (found_it != children.end()) { children.erase(found_it); @@ -275,16 +208,15 @@ void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) mParent = parent; if (parent) { - getFrameState().mParent = &parent->getFrameState(); parent->getChildren().push_back(this); parent->mNeedsSorting = true; } } -S32 LLFastTimer::NamedTimer::getDepth() +S32 LLFastTimer::DeclareTimer::getDepth() { S32 depth = 0; - NamedTimer* timerp = mParent; + DeclareTimer* timerp = mParent; while(timerp) { depth++; @@ -295,7 +227,7 @@ S32 LLFastTimer::NamedTimer::getDepth() } // static -void LLFastTimer::NamedTimer::processTimes() +void LLFastTimer::DeclareTimer::processTimes() { if (sCurFrameIndex < 0) return; @@ -306,14 +238,14 @@ void LLFastTimer::NamedTimer::processTimes() // sort child timers by name struct SortTimerByName { - bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2) + bool operator()(const LLFastTimer::DeclareTimer* i1, const LLFastTimer::DeclareTimer* i2) { return i1->getName() < i2->getName(); } }; //static -void LLFastTimer::NamedTimer::buildHierarchy() +void LLFastTimer::DeclareTimer::buildHierarchy() { if (sCurFrameIndex < 0 ) return; @@ -321,16 +253,16 @@ void LLFastTimer::NamedTimer::buildHierarchy() { for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - NamedTimer& timer = *it; - if (&timer == NamedTimerFactory::instance().getRootTimer()) continue; + DeclareTimer& timer = *it; + if (&timer == &DeclareTimer::getRootTimer()) continue; // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.getFrameState().mLastCaller && timer.mParent == NamedTimerFactory::instance().getRootTimer()) + if (timer.mLastCaller && timer.mParent == &DeclareTimer::getRootTimer()) { - timer.setParent(timer.getFrameState().mLastCaller->mTimer); + timer.setParent(timer.mLastCaller); // no need to push up tree on first use, flag can be set spuriously - timer.getFrameState().mMoveUpTree = false; + timer.mMoveUpTree = false; } } } @@ -338,22 +270,22 @@ void LLFastTimer::NamedTimer::buildHierarchy() // bump timers up tree if they've been flagged as being in the wrong place // do this in a bottom up order to promote descendants first before promoting ancestors // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(DeclareTimer::getRootTimer()); it != end_timer_tree_bottom_up(); ++it) { - NamedTimer* timerp = *it; + DeclareTimer* timerp = *it; // skip root timer - if (timerp == NamedTimerFactory::instance().getRootTimer()) continue; + if (timerp == &DeclareTimer::getRootTimer()) continue; - if (timerp->getFrameState().mMoveUpTree) + if (timerp->mMoveUpTree) { // since ancestors have already been visited, reparenting won't affect tree traversal //step up tree, bringing our descendants with us LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; timerp->setParent(timerp->getParent()->getParent()); - timerp->getFrameState().mMoveUpTree = false; + timerp->mMoveUpTree = false; // don't bubble up any ancestors until descendants are done bubbling up it.skipAncestors(); @@ -361,11 +293,11 @@ void LLFastTimer::NamedTimer::buildHierarchy() } // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(DeclareTimer::getRootTimer()); it != end_timer_tree(); ++it) { - NamedTimer* timerp = (*it); + DeclareTimer* timerp = (*it); if (timerp->mNeedsSorting) { std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); @@ -375,7 +307,7 @@ void LLFastTimer::NamedTimer::buildHierarchy() } //static -void LLFastTimer::NamedTimer::accumulateTimings() +void LLFastTimer::DeclareTimer::accumulateTimings() { U32 cur_time = getCPUClockCount32(); @@ -388,8 +320,8 @@ void LLFastTimer::NamedTimer::accumulateTimings() U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; - cur_data->mFrameState->mSelfTimeCounter += self_time_delta; - cur_data->mFrameState->mTotalTimeCounter += cumulative_time_delta; + cur_data->mTimerData->mSelfTimeCounter += self_time_delta; + cur_data->mTimerData->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; @@ -400,12 +332,12 @@ void LLFastTimer::NamedTimer::accumulateTimings() } // traverse tree in DFS post order, or bottom up - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(DeclareTimer::getRootTimer()); it != end_timer_tree_bottom_up(); ++it) { - NamedTimer* timerp = (*it); - timerp->mTreeTimeCounter = timerp->getFrameState().mSelfTimeCounter; + DeclareTimer* timerp = (*it); + timerp->mTreeTimeCounter = timerp->mSelfTimeCounter; for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) { timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; @@ -418,15 +350,15 @@ void LLFastTimer::NamedTimer::accumulateTimings() int hidx = cur_frame % HISTORY_NUM; timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; - timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); - timerp->mCallHistory[hidx] = timerp->getFrameState().mCalls; - timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->getFrameState().mCalls) / (cur_frame+1); + timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); + timerp->mCallHistory[hidx] = timerp->mCalls; + timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->mCalls) / (cur_frame+1); } } } // static -void LLFastTimer::NamedTimer::resetFrame() +void LLFastTimer::DeclareTimer::resetFrame() { if (sLog) { //output current frame counts to performance log @@ -435,11 +367,11 @@ void LLFastTimer::NamedTimer::resetFrame() if (call_count % 100 == 0) { LL_DEBUGS("FastTimers") << "countsPerSecond (32 bit): " << countsPerSecond() << LL_ENDL; - LL_DEBUGS("FastTimers") << "get_clock_count (64 bit): " << get_clock_count() << llendl; + LL_DEBUGS("FastTimers") << "get_clock_count (64 bit): " << get_clock_count() << LL_ENDL; LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; - LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64())/((F64)LLProcessorInfo().getCPUFrequency()*1000000.0) << LL_ENDL; + LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; } call_count++; @@ -451,14 +383,13 @@ void LLFastTimer::NamedTimer::resetFrame() { for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - NamedTimer& timer = *it; - FrameState& info = timer.getFrameState(); - sd[timer.getName()]["Time"] = (LLSD::Real) (info.mSelfTimeCounter*iclock_freq); - sd[timer.getName()]["Calls"] = (LLSD::Integer) info.mCalls; + DeclareTimer& timer = *it; + sd[timer.getName()]["Time"] = (LLSD::Real) (timer.mSelfTimeCounter*iclock_freq); + sd[timer.getName()]["Calls"] = (LLSD::Integer) timer.mCalls; // computing total time here because getting the root timer's getCountHistory // doesn't work correctly on the first frame - total_time = total_time + info.mSelfTimeCounter * iclock_freq; + total_time = total_time + timer.mSelfTimeCounter * iclock_freq; } } @@ -474,23 +405,16 @@ void LLFastTimer::NamedTimer::resetFrame() // reset for next frame for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - NamedTimer& timer = *it; - - FrameState& info = timer.getFrameState(); - info.mSelfTimeCounter = 0; - info.mCalls = 0; - info.mLastCaller = NULL; - info.mMoveUpTree = false; - // update parent pointer in timer state struct - if (timer.mParent) - { - info.mParent = &timer.mParent->getFrameState(); - } + DeclareTimer& timer = *it; + timer.mSelfTimeCounter = 0; + timer.mCalls = 0; + timer.mLastCaller = NULL; + timer.mMoveUpTree = false; } } //static -void LLFastTimer::NamedTimer::reset() +void LLFastTimer::DeclareTimer::reset() { resetFrame(); // reset frame data @@ -514,10 +438,10 @@ void LLFastTimer::NamedTimer::reset() { for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - NamedTimer& timer = *it; - if (&timer != NamedTimerFactory::instance().getRootTimer()) + DeclareTimer& timer = *it; + if (&timer != &DeclareTimer::getRootTimer()) { - timer.setParent(NamedTimerFactory::instance().getRootTimer()); + timer.setParent(&DeclareTimer::getRootTimer()); } timer.mCountAverage = 0; @@ -531,34 +455,29 @@ void LLFastTimer::NamedTimer::reset() sCurFrameIndex = 0; } -U32 LLFastTimer::NamedTimer::getHistoricalCount(S32 history_index) const +U32 LLFastTimer::DeclareTimer::getHistoricalCount(S32 history_index) const { - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::DeclareTimer::HISTORY_NUM; return mCountHistory[history_idx]; } -U32 LLFastTimer::NamedTimer::getHistoricalCalls(S32 history_index ) const +U32 LLFastTimer::DeclareTimer::getHistoricalCalls(S32 history_index ) const { - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::DeclareTimer::HISTORY_NUM; return mCallHistory[history_idx]; } -LLFastTimer::FrameState& LLFastTimer::NamedTimer::getFrameState() const -{ - return *mFrameState; -} - -std::vector::const_iterator LLFastTimer::NamedTimer::beginChildren() +std::vector::const_iterator LLFastTimer::DeclareTimer::beginChildren() { return mChildren.begin(); } -std::vector::const_iterator LLFastTimer::NamedTimer::endChildren() +std::vector::const_iterator LLFastTimer::DeclareTimer::endChildren() { return mChildren.end(); } -std::vector& LLFastTimer::NamedTimer::getChildren() +std::vector& LLFastTimer::DeclareTimer::getChildren() { return mChildren; } @@ -575,12 +494,12 @@ void LLFastTimer::nextFrame() if (!sPauseHistory) { - NamedTimer::processTimes(); + DeclareTimer::processTimes(); sLastFrameIndex = sCurFrameIndex++; } // get ready for next frame - NamedTimer::resetFrame(); + DeclareTimer::resetFrame(); sLastFrameTime = frame_time; } @@ -588,17 +507,17 @@ void LLFastTimer::nextFrame() void LLFastTimer::dumpCurTimes() { // accumulate timings, etc. - NamedTimer::processTimes(); + DeclareTimer::processTimes(); F64 clock_freq = (F64)countsPerSecond(); F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(DeclareTimer::getRootTimer()); it != end_timer_tree(); ++it) { - NamedTimer* timerp = (*it); + DeclareTimer* timerp = (*it); F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); // Don't bother with really brief times, keep output concise if (total_time_ms < 0.1) continue; @@ -621,7 +540,7 @@ void LLFastTimer::dumpCurTimes() //static void LLFastTimer::reset() { - NamedTimer::reset(); + DeclareTimer::reset(); } @@ -637,22 +556,3 @@ void LLFastTimer::writeLog(std::ostream& os) } } -//static -const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& name) -{ - return NamedTimerFactory::instance().getTimerByName(name); -} - -//LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) -//: mFrameState(state) -//{ -// U32 start_time = getCPUClockCount32(); -// mStartTime = start_time; -// mFrameState->mActiveCount++; -// LLFastTimer::sCurTimerData.mCurTimer = this; -// LLFastTimer::sCurTimerData.mFrameState = mFrameState; -// LLFastTimer::sCurTimerData.mChildTime = 0; -// mLastTimerData = LLFastTimer::sCurTimerData; -//} - - -- cgit v1.2.3 From c76ed72c609b80b08df6cebd68274c9da6d3de2c Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 12 Nov 2012 19:12:20 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system removed remnants of LLFastTimer::FrameState --- indra/llcommon/llfasttimer.cpp | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index c4839fed77..66452fd02a 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -140,15 +140,6 @@ U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer } #endif -LLFastTimer::FrameState::FrameState() -: mActiveCount(0), - mCalls(0), - mSelfTimeCounter(0), - mLastCaller(NULL), - mMoveUpTree(false) -{} - - LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open, DeclareTimer* parent) : mName(name), mCollapsed(true), @@ -156,7 +147,12 @@ LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open, Decl mTreeTimeCounter(0), mCountAverage(0), mCallAverage(0), - mNeedsSorting(false) + mNeedsSorting(false), + mActiveCount(0), + mCalls(0), + mSelfTimeCounter(0), + mLastCaller(NULL), + mMoveUpTree(false) { setCollapsed(!open); -- cgit v1.2.3 From 67ec47e6da389661934ed2ddfa55ca58455fa7e5 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Tue, 13 Nov 2012 17:10:10 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system moving fast timers into lltrace namespace and accumulation system --- indra/llcommon/llfasttimer.cpp | 186 +++++++++++++++++++++++------------------ 1 file changed, 104 insertions(+), 82 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 66452fd02a..cced0bdfa9 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -33,8 +33,10 @@ #include "lltreeiterators.h" #include "llsdserialize.h" #include "llunit.h" +#include "llsd.h" #include +#include #if LL_WINDOWS @@ -50,37 +52,40 @@ #error "architecture not supported" #endif +namespace LLTrace +{ + ////////////////////////////////////////////////////////////////////////////// // statics -S32 LLFastTimer::sCurFrameIndex = -1; -S32 LLFastTimer::sLastFrameIndex = -1; -U64 LLFastTimer::sLastFrameTime = LLFastTimer::getCPUClockCount64(); -bool LLFastTimer::sPauseHistory = 0; -bool LLFastTimer::sResetHistory = 0; -LLFastTimer::CurTimerData LLFastTimer::sCurTimerData; -BOOL LLFastTimer::sLog = FALSE; -std::string LLFastTimer::sLogName = ""; -BOOL LLFastTimer::sMetricLog = FALSE; -LLMutex* LLFastTimer::sLogLock = NULL; -std::queue LLFastTimer::sLogQueue; +S32 Time::sCurFrameIndex = -1; +S32 Time::sLastFrameIndex = -1; +U64 Time::sLastFrameTime = Time::getCPUClockCount64(); +bool Time::sPauseHistory = 0; +bool Time::sResetHistory = 0; +LLThreadLocalPointer Time::sCurTimerData; +bool Time::sLog = FALSE; +std::string Time::sLogName = ""; +bool Time::sMetricLog = FALSE; +static LLMutex* sLogLock = NULL; +static std::queue sLogQueue; #if LL_LINUX || LL_SOLARIS -U64 LLFastTimer::sClockResolution = 1000000000; // Nanosecond resolution +U64 Time::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution +U64 Time::sClockResolution = 1000000; // Microsecond resolution #endif // FIXME: move these declarations to the relevant modules // helper functions -typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; +typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; -static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::DeclareTimer& id) +static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(BlockTimer& id) { return timer_tree_bottom_up_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&BlockTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimer::endChildren), _1)); } static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() @@ -88,14 +93,14 @@ static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() return timer_tree_bottom_up_iterator_t(); } -typedef LLTreeDFSIter timer_tree_dfs_iterator_t; +typedef LLTreeDFSIter timer_tree_dfs_iterator_t; -static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::DeclareTimer& id) +static timer_tree_dfs_iterator_t begin_timer_tree(BlockTimer& id) { return timer_tree_dfs_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::DeclareTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&BlockTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimer::endChildren), _1)); } static timer_tree_dfs_iterator_t end_timer_tree() @@ -103,21 +108,21 @@ static timer_tree_dfs_iterator_t end_timer_tree() return timer_tree_dfs_iterator_t(); } -LLFastTimer::DeclareTimer& LLFastTimer::DeclareTimer::getRootTimer() +BlockTimer& BlockTimer::getRootTimer() { - static DeclareTimer root_timer("root", true, NULL); + static BlockTimer root_timer("root", true, NULL); return root_timer; } //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 Time::countsPerSecond() // counts per second for the *32-bit* timer { return sClockResolution >> 8; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 Time::countsPerSecond() // counts per second for the *32-bit* timer { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz @@ -140,19 +145,14 @@ U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer } #endif -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open, DeclareTimer* parent) -: mName(name), +BlockTimer::BlockTimer(const char* name, bool open, BlockTimer* parent) +: TraceType(name), mCollapsed(true), mParent(NULL), mTreeTimeCounter(0), mCountAverage(0), mCallAverage(0), - mNeedsSorting(false), - mActiveCount(0), - mCalls(0), - mSelfTimeCounter(0), - mLastCaller(NULL), - mMoveUpTree(false) + mNeedsSorting(false) { setCollapsed(!open); @@ -171,13 +171,13 @@ LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open, Decl memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); } -LLFastTimer::DeclareTimer::~DeclareTimer() +BlockTimer::~BlockTimer() { delete[] mCountHistory; delete[] mCallHistory; } -void LLFastTimer::DeclareTimer::setParent(DeclareTimer* parent) +void BlockTimer::setParent(BlockTimer* parent) { llassert_always(parent != this); llassert_always(parent != NULL); @@ -193,8 +193,8 @@ void LLFastTimer::DeclareTimer::setParent(DeclareTimer* parent) // subtract average timing from previous parent mParent->mCountAverage -= mCountAverage; - std::vector& children = mParent->getChildren(); - std::vector::iterator found_it = std::find(children.begin(), children.end(), this); + std::vector& children = mParent->getChildren(); + std::vector::iterator found_it = std::find(children.begin(), children.end(), this); if (found_it != children.end()) { children.erase(found_it); @@ -209,10 +209,10 @@ void LLFastTimer::DeclareTimer::setParent(DeclareTimer* parent) } } -S32 LLFastTimer::DeclareTimer::getDepth() +S32 BlockTimer::getDepth() { S32 depth = 0; - DeclareTimer* timerp = mParent; + BlockTimer* timerp = mParent; while(timerp) { depth++; @@ -223,9 +223,9 @@ S32 LLFastTimer::DeclareTimer::getDepth() } // static -void LLFastTimer::DeclareTimer::processTimes() +void BlockTimer::processTimes() { - if (sCurFrameIndex < 0) return; + if (Time::getCurFrameIndex() < 0) return; buildHierarchy(); accumulateTimings(); @@ -234,27 +234,27 @@ void LLFastTimer::DeclareTimer::processTimes() // sort child timers by name struct SortTimerByName { - bool operator()(const LLFastTimer::DeclareTimer* i1, const LLFastTimer::DeclareTimer* i2) + bool operator()(const BlockTimer* i1, const BlockTimer* i2) { return i1->getName() < i2->getName(); } }; //static -void LLFastTimer::DeclareTimer::buildHierarchy() +void BlockTimer::buildHierarchy() { - if (sCurFrameIndex < 0 ) return; + if (Time::getCurFrameIndex() < 0 ) return; // set up initial tree { - for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); it != end_it; ++it) { - DeclareTimer& timer = *it; - if (&timer == &DeclareTimer::getRootTimer()) continue; + BlockTimer& timer = *it; + if (&timer == &BlockTimer::getRootTimer()) continue; // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.mLastCaller && timer.mParent == &DeclareTimer::getRootTimer()) + if (timer.mLastCaller && timer.mParent == &BlockTimer::getRootTimer()) { timer.setParent(timer.mLastCaller); // no need to push up tree on first use, flag can be set spuriously @@ -266,13 +266,13 @@ void LLFastTimer::DeclareTimer::buildHierarchy() // bump timers up tree if they've been flagged as being in the wrong place // do this in a bottom up order to promote descendants first before promoting ancestors // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(DeclareTimer::getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(BlockTimer::getRootTimer()); it != end_timer_tree_bottom_up(); ++it) { - DeclareTimer* timerp = *it; + BlockTimer* timerp = *it; // skip root timer - if (timerp == &DeclareTimer::getRootTimer()) continue; + if (timerp == &BlockTimer::getRootTimer()) continue; if (timerp->mMoveUpTree) { @@ -289,11 +289,11 @@ void LLFastTimer::DeclareTimer::buildHierarchy() } // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(DeclareTimer::getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(BlockTimer::getRootTimer()); it != end_timer_tree(); ++it) { - DeclareTimer* timerp = (*it); + BlockTimer* timerp = (*it); if (timerp->mNeedsSorting) { std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); @@ -303,12 +303,12 @@ void LLFastTimer::DeclareTimer::buildHierarchy() } //static -void LLFastTimer::DeclareTimer::accumulateTimings() +void BlockTimer::accumulateTimings() { U32 cur_time = getCPUClockCount32(); // walk up stack of active timers and accumulate current time while leaving timing structures active - LLFastTimer* cur_timer = sCurTimerData.mCurTimer; + Time* cur_timer = sCurTimerData.mCurTimer; // root defined by parent pointing to self CurTimerData* cur_data = &sCurTimerData; while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) @@ -328,11 +328,11 @@ void LLFastTimer::DeclareTimer::accumulateTimings() } // traverse tree in DFS post order, or bottom up - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(DeclareTimer::getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(BlockTimer::getRootTimer()); it != end_timer_tree_bottom_up(); ++it) { - DeclareTimer* timerp = (*it); + BlockTimer* timerp = (*it); timerp->mTreeTimeCounter = timerp->mSelfTimeCounter; for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) { @@ -354,7 +354,7 @@ void LLFastTimer::DeclareTimer::accumulateTimings() } // static -void LLFastTimer::DeclareTimer::resetFrame() +void BlockTimer::resetFrame() { if (sLog) { //output current frame counts to performance log @@ -379,7 +379,7 @@ void LLFastTimer::DeclareTimer::resetFrame() { for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - DeclareTimer& timer = *it; + BlockTimer& timer = *it; sd[timer.getName()]["Time"] = (LLSD::Real) (timer.mSelfTimeCounter*iclock_freq); sd[timer.getName()]["Calls"] = (LLSD::Integer) timer.mCalls; @@ -401,7 +401,7 @@ void LLFastTimer::DeclareTimer::resetFrame() // reset for next frame for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - DeclareTimer& timer = *it; + BlockTimer& timer = *it; timer.mSelfTimeCounter = 0; timer.mCalls = 0; timer.mLastCaller = NULL; @@ -410,7 +410,7 @@ void LLFastTimer::DeclareTimer::resetFrame() } //static -void LLFastTimer::DeclareTimer::reset() +void BlockTimer::reset() { resetFrame(); // reset frame data @@ -420,7 +420,7 @@ void LLFastTimer::DeclareTimer::reset() // root defined by parent pointing to self CurTimerData* cur_data = &sCurTimerData; - LLFastTimer* cur_timer = cur_data->mCurTimer; + Time* cur_timer = cur_data->mCurTimer; while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { cur_timer->mStartTime = cur_time; @@ -434,10 +434,10 @@ void LLFastTimer::DeclareTimer::reset() { for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) { - DeclareTimer& timer = *it; - if (&timer != &DeclareTimer::getRootTimer()) + BlockTimer& timer = *it; + if (&timer != &BlockTimer::getRootTimer()) { - timer.setParent(&DeclareTimer::getRootTimer()); + timer.setParent(&BlockTimer::getRootTimer()); } timer.mCountAverage = 0; @@ -451,35 +451,35 @@ void LLFastTimer::DeclareTimer::reset() sCurFrameIndex = 0; } -U32 LLFastTimer::DeclareTimer::getHistoricalCount(S32 history_index) const +U32 BlockTimer::getHistoricalCount(S32 history_index) const { - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::DeclareTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % BlockTimer::HISTORY_NUM; return mCountHistory[history_idx]; } -U32 LLFastTimer::DeclareTimer::getHistoricalCalls(S32 history_index ) const +U32 BlockTimer::getHistoricalCalls(S32 history_index ) const { - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::DeclareTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % BlockTimer::HISTORY_NUM; return mCallHistory[history_idx]; } -std::vector::const_iterator LLFastTimer::DeclareTimer::beginChildren() +std::vector::const_iterator BlockTimer::beginChildren() { return mChildren.begin(); } -std::vector::const_iterator LLFastTimer::DeclareTimer::endChildren() +std::vector::const_iterator BlockTimer::endChildren() { return mChildren.end(); } -std::vector& LLFastTimer::DeclareTimer::getChildren() +std::vector& BlockTimer::getChildren() { return mChildren; } //static -void LLFastTimer::nextFrame() +void Time::nextFrame() { countsPerSecond(); // good place to calculate clock frequency U64 frame_time = getCPUClockCount64(); @@ -490,30 +490,30 @@ void LLFastTimer::nextFrame() if (!sPauseHistory) { - DeclareTimer::processTimes(); + BlockTimer::processTimes(); sLastFrameIndex = sCurFrameIndex++; } // get ready for next frame - DeclareTimer::resetFrame(); + BlockTimer::resetFrame(); sLastFrameTime = frame_time; } //static -void LLFastTimer::dumpCurTimes() +void Time::dumpCurTimes() { // accumulate timings, etc. - DeclareTimer::processTimes(); + BlockTimer::processTimes(); F64 clock_freq = (F64)countsPerSecond(); F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(DeclareTimer::getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(BlockTimer::getRootTimer()); it != end_timer_tree(); ++it) { - DeclareTimer* timerp = (*it); + BlockTimer* timerp = (*it); F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); // Don't bother with really brief times, keep output concise if (total_time_ms < 0.1) continue; @@ -534,14 +534,14 @@ void LLFastTimer::dumpCurTimes() } //static -void LLFastTimer::reset() +void Time::reset() { - DeclareTimer::reset(); + BlockTimer::reset(); } //static -void LLFastTimer::writeLog(std::ostream& os) +void Time::writeLog(std::ostream& os) { while (!sLogQueue.empty()) { @@ -552,3 +552,25 @@ void LLFastTimer::writeLog(std::ostream& os) } } + +void LLTrace::TimerAccumulator::addSamples( const LLTrace::TimerAccumulator& other ) +{ + mSelfTimeCounter += other.mSelfTimeCounter; + mTotalTimeCounter += other.mTotalTimeCounter; + mCalls += other.mCalls; + if (!mLastCaller) + { + mLastCaller = other.mLastCaller; + } + + //mActiveCount stays the same; + mMoveUpTree |= other.mMoveUpTree; +} + +void LLTrace::TimerAccumulator::reset( const LLTrace::TimerAccumulator* other ) +{ + mTotalTimeCounter = 0; + mSelfTimeCounter = 0; + mCalls = 0; +} +} -- cgit v1.2.3 From 9d77e030d9a0d23cebce616631677459eec1612c Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 14 Nov 2012 23:52:27 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system cleaning up build moved most includes of windows.h to llwin32headers.h to disable min/max macros, etc streamlined Time class and consolidated functionality in BlockTimer class llfasttimer is no longer included via llstring.h, so had to add it manually in several places --- indra/llcommon/llfasttimer.cpp | 120 +++++++++++++++++++++++------------------ 1 file changed, 67 insertions(+), 53 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index cced0bdfa9..d007f76e5f 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -58,22 +58,22 @@ namespace LLTrace ////////////////////////////////////////////////////////////////////////////// // statics -S32 Time::sCurFrameIndex = -1; -S32 Time::sLastFrameIndex = -1; -U64 Time::sLastFrameTime = Time::getCPUClockCount64(); -bool Time::sPauseHistory = 0; -bool Time::sResetHistory = 0; -LLThreadLocalPointer Time::sCurTimerData; -bool Time::sLog = FALSE; -std::string Time::sLogName = ""; -bool Time::sMetricLog = FALSE; +S32 BlockTimer::sCurFrameIndex = -1; +S32 BlockTimer::sLastFrameIndex = -1; +U64 BlockTimer::sLastFrameTime = BlockTimer::getCPUClockCount64(); +bool BlockTimer::sPauseHistory = 0; +bool BlockTimer::sResetHistory = 0; +LLThreadLocalPointer BlockTimer::sCurTimerData; +bool BlockTimer::sLog = false; +std::string BlockTimer::sLogName = ""; +bool BlockTimer::sMetricLog = false; static LLMutex* sLogLock = NULL; static std::queue sLogQueue; #if LL_LINUX || LL_SOLARIS -U64 Time::sClockResolution = 1000000000; // Nanosecond resolution +U64 BlockTimer::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 Time::sClockResolution = 1000000; // Microsecond resolution +U64 BlockTimer::sClockResolution = 1000000; // Microsecond resolution #endif // FIXME: move these declarations to the relevant modules @@ -114,15 +114,22 @@ BlockTimer& BlockTimer::getRootTimer() return root_timer; } +void BlockTimer::pushLog(LLSD log) +{ + LLMutexLock lock(sLogLock); + + sLogQueue.push(log); +} + //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 Time::countsPerSecond() // counts per second for the *32-bit* timer +U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer { return sClockResolution >> 8; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 Time::countsPerSecond() // counts per second for the *32-bit* timer +U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz @@ -225,7 +232,7 @@ S32 BlockTimer::getDepth() // static void BlockTimer::processTimes() { - if (Time::getCurFrameIndex() < 0) return; + if (getCurFrameIndex() < 0) return; buildHierarchy(); accumulateTimings(); @@ -243,7 +250,7 @@ struct SortTimerByName //static void BlockTimer::buildHierarchy() { - if (Time::getCurFrameIndex() < 0 ) return; + if (getCurFrameIndex() < 0 ) return; // set up initial tree { @@ -254,11 +261,11 @@ void BlockTimer::buildHierarchy() // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.mLastCaller && timer.mParent == &BlockTimer::getRootTimer()) + if (timer.getPrimaryAccumulator().mLastCaller && timer.mParent == &BlockTimer::getRootTimer()) { - timer.setParent(timer.mLastCaller); + timer.setParent(timer.getPrimaryAccumulator().mLastCaller); // no need to push up tree on first use, flag can be set spuriously - timer.mMoveUpTree = false; + timer.getPrimaryAccumulator().mMoveUpTree = false; } } } @@ -274,14 +281,14 @@ void BlockTimer::buildHierarchy() // skip root timer if (timerp == &BlockTimer::getRootTimer()) continue; - if (timerp->mMoveUpTree) + if (timerp->getPrimaryAccumulator().mMoveUpTree) { - // since ancestors have already been visited, reparenting won't affect tree traversal + // since ancestors have already been visited, re-parenting won't affect tree traversal //step up tree, bringing our descendants with us LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; timerp->setParent(timerp->getParent()->getParent()); - timerp->mMoveUpTree = false; + timerp->getPrimaryAccumulator().mMoveUpTree = false; // don't bubble up any ancestors until descendants are done bubbling up it.skipAncestors(); @@ -308,21 +315,23 @@ void BlockTimer::accumulateTimings() U32 cur_time = getCPUClockCount32(); // walk up stack of active timers and accumulate current time while leaving timing structures active - Time* cur_timer = sCurTimerData.mCurTimer; + Time* cur_timer = sCurTimerData->mCurTimer; // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; + CurTimerData* cur_data = sCurTimerData.get(); + TimerAccumulator& accumulator = sCurTimerData->mTimerData->getPrimaryAccumulator(); while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; - cur_data->mTimerData->mSelfTimeCounter += self_time_delta; - cur_data->mTimerData->mTotalTimeCounter += cumulative_time_delta; + accumulator.mSelfTimeCounter += self_time_delta; + accumulator.mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; cur_data = &cur_timer->mLastTimerData; cur_data->mChildTime += cumulative_time_delta; + accumulator = cur_data->mTimerData->getPrimaryAccumulator(); cur_timer = cur_timer->mLastTimerData.mCurTimer; } @@ -333,13 +342,14 @@ void BlockTimer::accumulateTimings() ++it) { BlockTimer* timerp = (*it); - timerp->mTreeTimeCounter = timerp->mSelfTimeCounter; + TimerAccumulator& accumulator = timerp->getPrimaryAccumulator(); + timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) { timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; } - S32 cur_frame = sCurFrameIndex; + S32 cur_frame = getCurFrameIndex(); if (cur_frame >= 0) { // update timer history @@ -347,8 +357,8 @@ void BlockTimer::accumulateTimings() timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); - timerp->mCallHistory[hidx] = timerp->mCalls; - timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->mCalls) / (cur_frame+1); + timerp->mCallHistory[hidx] = accumulator.mCalls; + timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + accumulator.mCalls) / (cur_frame+1); } } } @@ -377,15 +387,19 @@ void BlockTimer::resetFrame() LLSD sd; { - for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) { BlockTimer& timer = *it; - sd[timer.getName()]["Time"] = (LLSD::Real) (timer.mSelfTimeCounter*iclock_freq); - sd[timer.getName()]["Calls"] = (LLSD::Integer) timer.mCalls; + TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); + sd[timer.getName()]["Time"] = (LLSD::Real) (accumulator.mSelfTimeCounter*iclock_freq); + sd[timer.getName()]["Calls"] = (LLSD::Integer) accumulator.mCalls; // computing total time here because getting the root timer's getCountHistory // doesn't work correctly on the first frame - total_time = total_time + timer.mSelfTimeCounter * iclock_freq; + total_time = total_time + accumulator.mSelfTimeCounter * iclock_freq; } } @@ -399,13 +413,17 @@ void BlockTimer::resetFrame() } // reset for next frame - for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) { BlockTimer& timer = *it; - timer.mSelfTimeCounter = 0; - timer.mCalls = 0; - timer.mLastCaller = NULL; - timer.mMoveUpTree = false; + TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); + accumulator.mSelfTimeCounter = 0; + accumulator.mCalls = 0; + accumulator.mLastCaller = NULL; + accumulator.mMoveUpTree = false; } } @@ -419,7 +437,7 @@ void BlockTimer::reset() U32 cur_time = getCPUClockCount32(); // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; + CurTimerData* cur_data = sCurTimerData.get(); Time* cur_timer = cur_data->mCurTimer; while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { @@ -432,7 +450,10 @@ void BlockTimer::reset() // reset all history { - for (instance_iter it = beginInstances(), end_it = endInstances(); it != end_it; ++it) + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) { BlockTimer& timer = *it; if (&timer != &BlockTimer::getRootTimer()) @@ -453,13 +474,13 @@ void BlockTimer::reset() U32 BlockTimer::getHistoricalCount(S32 history_index) const { - S32 history_idx = (getLastFrameIndex() + history_index) % BlockTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % HISTORY_NUM; return mCountHistory[history_idx]; } U32 BlockTimer::getHistoricalCalls(S32 history_index ) const { - S32 history_idx = (getLastFrameIndex() + history_index) % BlockTimer::HISTORY_NUM; + S32 history_idx = (getLastFrameIndex() + history_index) % HISTORY_NUM; return mCallHistory[history_idx]; } @@ -479,10 +500,10 @@ std::vector& BlockTimer::getChildren() } //static -void Time::nextFrame() +void BlockTimer::nextFrame() { - countsPerSecond(); // good place to calculate clock frequency - U64 frame_time = getCPUClockCount64(); + BlockTimer::countsPerSecond(); // good place to calculate clock frequency + U64 frame_time = BlockTimer::getCPUClockCount64(); if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) { llinfos << "Slow frame, fast timers inaccurate" << llendl; @@ -505,7 +526,7 @@ void Time::dumpCurTimes() // accumulate timings, etc. BlockTimer::processTimes(); - F64 clock_freq = (F64)countsPerSecond(); + F64 clock_freq = (F64)BlockTimer::countsPerSecond(); F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds // walk over timers in depth order and output timings @@ -533,13 +554,6 @@ void Time::dumpCurTimes() } } -//static -void Time::reset() -{ - BlockTimer::reset(); -} - - //static void Time::writeLog(std::ostream& os) { -- cgit v1.2.3 From c136b432140f892a56d4996d5ed77e903ff0b32d Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 15 Nov 2012 19:46:09 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system eliminated min and max macros from windows.h got rest of viewer to compile against llfasttimer changes --- indra/llcommon/llfasttimer.cpp | 5 +++++ 1 file changed, 5 insertions(+) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index d007f76e5f..4ecca12832 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -121,6 +121,11 @@ void BlockTimer::pushLog(LLSD log) sLogQueue.push(log); } +void BlockTimer::setLogLock(LLMutex* lock) +{ + sLogLock = lock; +} + //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -- cgit v1.2.3 From 6db6cb39f41e921e75970d1570a74cf35d353a35 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 16 Nov 2012 23:02:53 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system got new fast timer code to compile and run --- indra/llcommon/llfasttimer.cpp | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 4ecca12832..e1549b4bff 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -336,7 +336,10 @@ void BlockTimer::accumulateTimings() cur_data = &cur_timer->mLastTimerData; cur_data->mChildTime += cumulative_time_delta; - accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + if (cur_data->mTimerData) + { + accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + } cur_timer = cur_timer->mLastTimerData.mCurTimer; } @@ -572,6 +575,14 @@ void Time::writeLog(std::ostream& os) } +LLTrace::TimerAccumulator::TimerAccumulator() : mSelfTimeCounter(0), + mTotalTimeCounter(0), + mCalls(0), + mLastCaller(NULL), + mActiveCount(0), + mMoveUpTree(false) +{} + void LLTrace::TimerAccumulator::addSamples( const LLTrace::TimerAccumulator& other ) { mSelfTimeCounter += other.mSelfTimeCounter; -- cgit v1.2.3 From 1c894c05c10ef37be6507ee4bc4e9173506adfb6 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Tue, 27 Nov 2012 17:26:12 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system hunting down bad values and crashes --- indra/llcommon/llfasttimer.cpp | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e1549b4bff..16dd21332c 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -177,8 +177,8 @@ BlockTimer::BlockTimer(const char* name, bool open, BlockTimer* parent) mParent = this; } - mCountHistory = new U32[HISTORY_NUM]; - memset(mCountHistory, 0, sizeof(U32) * HISTORY_NUM); + mCountHistory = new U64[HISTORY_NUM]; + memset(mCountHistory, 0, sizeof(U64) * HISTORY_NUM); mCallHistory = new U32[HISTORY_NUM]; memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); } @@ -266,9 +266,12 @@ void BlockTimer::buildHierarchy() // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.getPrimaryAccumulator().mLastCaller && timer.mParent == &BlockTimer::getRootTimer()) + if (timer.mParent == &BlockTimer::getRootTimer()) { - timer.setParent(timer.getPrimaryAccumulator().mLastCaller); + if (timer.getPrimaryAccumulator().mLastCaller) + { + timer.setParent(timer.getPrimaryAccumulator().mLastCaller); + } // no need to push up tree on first use, flag can be set spuriously timer.getPrimaryAccumulator().mMoveUpTree = false; } @@ -317,7 +320,7 @@ void BlockTimer::buildHierarchy() //static void BlockTimer::accumulateTimings() { - U32 cur_time = getCPUClockCount32(); + U64 cur_time = getCPUClockCount64(); // walk up stack of active timers and accumulate current time while leaving timing structures active Time* cur_timer = sCurTimerData->mCurTimer; @@ -326,8 +329,8 @@ void BlockTimer::accumulateTimings() TimerAccumulator& accumulator = sCurTimerData->mTimerData->getPrimaryAccumulator(); while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { - U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; + U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; accumulator.mSelfTimeCounter += self_time_delta; accumulator.mTotalTimeCounter += cumulative_time_delta; @@ -429,6 +432,7 @@ void BlockTimer::resetFrame() BlockTimer& timer = *it; TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); accumulator.mSelfTimeCounter = 0; + accumulator.mTotalTimeCounter = 0; accumulator.mCalls = 0; accumulator.mLastCaller = NULL; accumulator.mMoveUpTree = false; @@ -442,7 +446,7 @@ void BlockTimer::reset() // walk up stack of active timers and reset start times to current time // effectively zeroing out any accumulated time - U32 cur_time = getCPUClockCount32(); + U64 cur_time = getCPUClockCount64(); // root defined by parent pointing to self CurTimerData* cur_data = sCurTimerData.get(); @@ -471,7 +475,7 @@ void BlockTimer::reset() timer.mCountAverage = 0; timer.mCallAverage = 0; - memset(timer.mCountHistory, 0, sizeof(U32) * HISTORY_NUM); + memset(timer.mCountHistory, 0, sizeof(U64) * HISTORY_NUM); memset(timer.mCallHistory, 0, sizeof(U32) * HISTORY_NUM); } } @@ -480,7 +484,7 @@ void BlockTimer::reset() sCurFrameIndex = 0; } -U32 BlockTimer::getHistoricalCount(S32 history_index) const +U64 BlockTimer::getHistoricalCount(S32 history_index) const { S32 history_idx = (getLastFrameIndex() + history_index) % HISTORY_NUM; return mCountHistory[history_idx]; -- cgit v1.2.3 From 93aca485ba08a82a6bd3a2fc31deca18af0d1478 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Tue, 27 Nov 2012 20:17:37 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system fixed precision of fast timer counts --- indra/llcommon/llfasttimer.cpp | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e1549b4bff..9701a41dc5 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -317,7 +317,7 @@ void BlockTimer::buildHierarchy() //static void BlockTimer::accumulateTimings() { - U32 cur_time = getCPUClockCount32(); + U64 cur_time = getCPUClockCount64(); // walk up stack of active timers and accumulate current time while leaving timing structures active Time* cur_timer = sCurTimerData->mCurTimer; @@ -389,7 +389,7 @@ void BlockTimer::resetFrame() } call_count++; - F64 iclock_freq = 1000.0 / countsPerSecond(); // good place to calculate clock frequency + F64 iclock_freq = 1000.0 / get_clock_count(); // good place to calculate clock frequency F64 total_time = 0; LLSD sd; @@ -442,7 +442,7 @@ void BlockTimer::reset() // walk up stack of active timers and reset start times to current time // effectively zeroing out any accumulated time - U32 cur_time = getCPUClockCount32(); + U64 cur_time = getCPUClockCount64(); // root defined by parent pointing to self CurTimerData* cur_data = sCurTimerData.get(); @@ -510,7 +510,7 @@ std::vector& BlockTimer::getChildren() //static void BlockTimer::nextFrame() { - BlockTimer::countsPerSecond(); // good place to calculate clock frequency + get_clock_count(); // good place to calculate clock frequency U64 frame_time = BlockTimer::getCPUClockCount64(); if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) { @@ -534,7 +534,7 @@ void Time::dumpCurTimes() // accumulate timings, etc. BlockTimer::processTimes(); - F64 clock_freq = (F64)BlockTimer::countsPerSecond(); + F64 clock_freq = (F64)get_clock_count(); F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds // walk over timers in depth order and output timings -- cgit v1.2.3 From 02d503bf8f8890c6d4b57dd09a1fde2973715b75 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 29 Nov 2012 00:43:25 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system moved runtime timer tree topology information to separate array instead of recording stack --- indra/llcommon/llfasttimer.cpp | 85 ++++++++++++++++++++++-------------------- 1 file changed, 45 insertions(+), 40 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e88a5a9ed1..1b3498cce3 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -58,24 +58,27 @@ namespace LLTrace ////////////////////////////////////////////////////////////////////////////// // statics -S32 BlockTimer::sCurFrameIndex = -1; -S32 BlockTimer::sLastFrameIndex = -1; -U64 BlockTimer::sLastFrameTime = BlockTimer::getCPUClockCount64(); -bool BlockTimer::sPauseHistory = 0; -bool BlockTimer::sResetHistory = 0; -LLThreadLocalPointer BlockTimer::sCurTimerData; -bool BlockTimer::sLog = false; -std::string BlockTimer::sLogName = ""; -bool BlockTimer::sMetricLog = false; -static LLMutex* sLogLock = NULL; -static std::queue sLogQueue; +S32 BlockTimer::sCurFrameIndex = -1; +S32 BlockTimer::sLastFrameIndex = -1; +U64 BlockTimer::sLastFrameTime = BlockTimer::getCPUClockCount64(); +bool BlockTimer::sPauseHistory = 0; +bool BlockTimer::sResetHistory = 0; +bool BlockTimer::sLog = false; +std::string BlockTimer::sLogName = ""; +bool BlockTimer::sMetricLog = false; #if LL_LINUX || LL_SOLARIS -U64 BlockTimer::sClockResolution = 1000000000; // Nanosecond resolution +U64 BlockTimer::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 BlockTimer::sClockResolution = 1000000; // Microsecond resolution +U64 BlockTimer::sClockResolution = 1000000; // Microsecond resolution #endif +LLThreadLocalPointer BlockTimer::sCurTimerData; + +static LLMutex* sLogLock = NULL; +static std::queue sLogQueue; + + // FIXME: move these declarations to the relevant modules // helper functions @@ -108,6 +111,7 @@ static timer_tree_dfs_iterator_t end_timer_tree() return timer_tree_dfs_iterator_t(); } + BlockTimer& BlockTimer::getRootTimer() { static BlockTimer root_timer("root", true, NULL); @@ -142,7 +146,7 @@ U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer // we drop the low-order byte in our timers, so report a lower frequency #else - // If we're not using RDTSC, each fasttimer tick is just a performance counter tick. + // If we're not using RDTSC, each fast timer tick is just a performance counter tick. // Not redefining the clock frequency itself (in llprocessor.cpp/calculate_cpu_frequency()) // since that would change displayed MHz stats for CPUs static bool firstcall = true; @@ -268,17 +272,19 @@ void BlockTimer::buildHierarchy() // when this timer was called if (timer.mParent == &BlockTimer::getRootTimer()) { - if (timer.getPrimaryAccumulator().mLastCaller) - { - timer.setParent(timer.getPrimaryAccumulator().mLastCaller); + TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + + if (tree_node.mLastCaller) + { + timer.setParent(tree_node.mLastCaller); } // no need to push up tree on first use, flag can be set spuriously - timer.getPrimaryAccumulator().mMoveUpTree = false; + tree_node.mMoveUpTree = false; } } } - // bump timers up tree if they've been flagged as being in the wrong place + // bump timers up tree if they have been flagged as being in the wrong place // do this in a bottom up order to promote descendants first before promoting ancestors // this preserves partial order derived from current frame's observations for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(BlockTimer::getRootTimer()); @@ -288,15 +294,16 @@ void BlockTimer::buildHierarchy() BlockTimer* timerp = *it; // skip root timer if (timerp == &BlockTimer::getRootTimer()) continue; + TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timerp->getIndex()]; - if (timerp->getPrimaryAccumulator().mMoveUpTree) + if (tree_node.mMoveUpTree) { // since ancestors have already been visited, re-parenting won't affect tree traversal //step up tree, bringing our descendants with us LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; timerp->setParent(timerp->getParent()->getParent()); - timerp->getPrimaryAccumulator().mMoveUpTree = false; + tree_node.mMoveUpTree = false; // don't bubble up any ancestors until descendants are done bubbling up it.skipAncestors(); @@ -322,11 +329,11 @@ void BlockTimer::accumulateTimings() { U64 cur_time = getCPUClockCount64(); - // walk up stack of active timers and accumulate current time while leaving timing structures active - Time* cur_timer = sCurTimerData->mCurTimer; // root defined by parent pointing to self CurTimerData* cur_data = sCurTimerData.get(); - TimerAccumulator& accumulator = sCurTimerData->mTimerData->getPrimaryAccumulator(); + // walk up stack of active timers and accumulate current time while leaving timing structures active + Time* cur_timer = cur_data->mCurTimer; + TimerAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; @@ -431,11 +438,13 @@ void BlockTimer::resetFrame() { BlockTimer& timer = *it; TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); + TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + accumulator.mSelfTimeCounter = 0; accumulator.mTotalTimeCounter = 0; accumulator.mCalls = 0; - accumulator.mLastCaller = NULL; - accumulator.mMoveUpTree = false; + tree_node.mLastCaller = NULL; + tree_node.mMoveUpTree = false; } } @@ -579,32 +588,28 @@ void Time::writeLog(std::ostream& os) } -LLTrace::TimerAccumulator::TimerAccumulator() : mSelfTimeCounter(0), +TimerAccumulator::TimerAccumulator() : mSelfTimeCounter(0), mTotalTimeCounter(0), - mCalls(0), - mLastCaller(NULL), - mActiveCount(0), - mMoveUpTree(false) + mCalls(0) {} -void LLTrace::TimerAccumulator::addSamples( const LLTrace::TimerAccumulator& other ) +void TimerAccumulator::addSamples( const TimerAccumulator& other ) { mSelfTimeCounter += other.mSelfTimeCounter; mTotalTimeCounter += other.mTotalTimeCounter; mCalls += other.mCalls; - if (!mLastCaller) - { - mLastCaller = other.mLastCaller; - } - - //mActiveCount stays the same; - mMoveUpTree |= other.mMoveUpTree; } -void LLTrace::TimerAccumulator::reset( const LLTrace::TimerAccumulator* other ) +void TimerAccumulator::reset( const TimerAccumulator* other ) { mTotalTimeCounter = 0; mSelfTimeCounter = 0; mCalls = 0; } + +TimerTreeNode::TimerTreeNode() +: mLastCaller(NULL), + mActiveCount(0), + mMoveUpTree(false) +{} } -- cgit v1.2.3 From ca2207bd35c33b13b122f875a5a7d218f94ca3fc Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Sat, 1 Dec 2012 00:17:04 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system fixed scale of reported times moved reset calls to happen at same time so we don't show partial results --- indra/llcommon/llfasttimer.cpp | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 1b3498cce3..19676cc0c6 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -144,7 +144,6 @@ U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz static LLUnit sCPUClockFrequency = LLProcessorInfo().getCPUFrequency(); - // we drop the low-order byte in our timers, so report a lower frequency #else // If we're not using RDTSC, each fast timer tick is just a performance counter tick. // Not redefining the clock frequency itself (in llprocessor.cpp/calculate_cpu_frequency()) @@ -157,7 +156,7 @@ U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer firstcall = false; } #endif - return sCPUClockFrequency >> 8; + return sCPUClockFrequency; } #endif @@ -390,8 +389,7 @@ void BlockTimer::resetFrame() static S32 call_count = 0; if (call_count % 100 == 0) { - LL_DEBUGS("FastTimers") << "countsPerSecond (32 bit): " << countsPerSecond() << LL_ENDL; - LL_DEBUGS("FastTimers") << "get_clock_count (64 bit): " << get_clock_count() << LL_ENDL; + LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL; LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; -- cgit v1.2.3 From 13e4edf1cd664864afa585bc83bbe99d4f743326 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Sun, 2 Dec 2012 23:00:36 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system started moving fast timer historical stats over to LLTrace periodic recording --- indra/llcommon/llfasttimer.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 19676cc0c6..e33cb76eff 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -133,12 +133,12 @@ void BlockTimer::setLogLock(LLMutex* lock) //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 BlockTimer::countsPerSecond() // counts per second for the *64-bit* timer { - return sClockResolution >> 8; + return sClockResolution; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 BlockTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 BlockTimer::countsPerSecond() // counts per second for the *64-bit* timer { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz -- cgit v1.2.3 From 407e5013f3845208e0a60e26e8f0a7fad997df5d Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 3 Dec 2012 19:54:53 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system converted fast timer view over to new lltrace mechanisms --- indra/llcommon/llfasttimer.cpp | 538 +++++++++++++++++------------------------ 1 file changed, 228 insertions(+), 310 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e33cb76eff..cf7655acf7 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -34,6 +34,7 @@ #include "llsdserialize.h" #include "llunit.h" #include "llsd.h" +#include "lltracerecording.h" #include #include @@ -58,22 +59,22 @@ namespace LLTrace ////////////////////////////////////////////////////////////////////////////// // statics -S32 BlockTimer::sCurFrameIndex = -1; -S32 BlockTimer::sLastFrameIndex = -1; -U64 BlockTimer::sLastFrameTime = BlockTimer::getCPUClockCount64(); -bool BlockTimer::sPauseHistory = 0; -bool BlockTimer::sResetHistory = 0; -bool BlockTimer::sLog = false; -std::string BlockTimer::sLogName = ""; -bool BlockTimer::sMetricLog = false; +S32 TimeBlock::sCurFrameIndex = -1; +S32 TimeBlock::sLastFrameIndex = -1; +U64 TimeBlock::sLastFrameTime = TimeBlock::getCPUClockCount64(); +bool TimeBlock::sPauseHistory = 0; +bool TimeBlock::sResetHistory = 0; +bool TimeBlock::sLog = false; +std::string TimeBlock::sLogName = ""; +bool TimeBlock::sMetricLog = false; #if LL_LINUX || LL_SOLARIS -U64 BlockTimer::sClockResolution = 1000000000; // Nanosecond resolution +U64 TimeBlock::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 BlockTimer::sClockResolution = 1000000; // Microsecond resolution +U64 TimeBlock::sClockResolution = 1000000; // Microsecond resolution #endif -LLThreadLocalPointer BlockTimer::sCurTimerData; +LLThreadLocalPointer TimeBlock::sCurTimerData; static LLMutex* sLogLock = NULL; static std::queue sLogQueue; @@ -82,13 +83,13 @@ static std::queue sLogQueue; // FIXME: move these declarations to the relevant modules // helper functions -typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; +typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; -static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(BlockTimer& id) +static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(TimeBlock& id) { return timer_tree_bottom_up_iterator_t(&id, - boost::bind(boost::mem_fn(&BlockTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&BlockTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&TimeBlock::beginChildren), _1), + boost::bind(boost::mem_fn(&TimeBlock::endChildren), _1)); } static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() @@ -96,14 +97,14 @@ static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() return timer_tree_bottom_up_iterator_t(); } -typedef LLTreeDFSIter timer_tree_dfs_iterator_t; +typedef LLTreeDFSIter timer_tree_dfs_iterator_t; -static timer_tree_dfs_iterator_t begin_timer_tree(BlockTimer& id) +static timer_tree_dfs_iterator_t begin_timer_tree(TimeBlock& id) { return timer_tree_dfs_iterator_t(&id, - boost::bind(boost::mem_fn(&BlockTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&BlockTimer::endChildren), _1)); + boost::bind(boost::mem_fn(&TimeBlock::beginChildren), _1), + boost::bind(boost::mem_fn(&TimeBlock::endChildren), _1)); } static timer_tree_dfs_iterator_t end_timer_tree() @@ -112,20 +113,29 @@ static timer_tree_dfs_iterator_t end_timer_tree() } -BlockTimer& BlockTimer::getRootTimer() +// sort child timers by name +struct SortTimerByName { - static BlockTimer root_timer("root", true, NULL); + bool operator()(const TimeBlock* i1, const TimeBlock* i2) + { + return i1->getName() < i2->getName(); + } +}; + +TimeBlock& TimeBlock::getRootTimer() +{ + static TimeBlock root_timer("root", true, NULL); return root_timer; } -void BlockTimer::pushLog(LLSD log) +void TimeBlock::pushLog(LLSD log) { LLMutexLock lock(sLogLock); sLogQueue.push(log); } -void BlockTimer::setLogLock(LLMutex* lock) +void TimeBlock::setLogLock(LLMutex* lock) { sLogLock = lock; } @@ -133,12 +143,12 @@ void BlockTimer::setLogLock(LLMutex* lock) //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 BlockTimer::countsPerSecond() // counts per second for the *64-bit* timer +U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer { return sClockResolution; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 BlockTimer::countsPerSecond() // counts per second for the *64-bit* timer +U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz @@ -160,13 +170,10 @@ U64 BlockTimer::countsPerSecond() // counts per second for the *64-bit* timer } #endif -BlockTimer::BlockTimer(const char* name, bool open, BlockTimer* parent) +TimeBlock::TimeBlock(const char* name, bool open, TimeBlock* parent) : TraceType(name), mCollapsed(true), mParent(NULL), - mTreeTimeCounter(0), - mCountAverage(0), - mCallAverage(0), mNeedsSorting(false) { setCollapsed(!open); @@ -179,37 +186,26 @@ BlockTimer::BlockTimer(const char* name, bool open, BlockTimer* parent) { mParent = this; } - - mCountHistory = new U64[HISTORY_NUM]; - memset(mCountHistory, 0, sizeof(U64) * HISTORY_NUM); - mCallHistory = new U32[HISTORY_NUM]; - memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); } -BlockTimer::~BlockTimer() -{ - delete[] mCountHistory; - delete[] mCallHistory; -} - -void BlockTimer::setParent(BlockTimer* parent) +void TimeBlock::setParent(TimeBlock* parent) { llassert_always(parent != this); llassert_always(parent != NULL); if (mParent) { - // subtract our accumulated from previous parent - for (S32 i = 0; i < HISTORY_NUM; i++) - { - mParent->mCountHistory[i] -= mCountHistory[i]; - } + //// subtract our accumulated from previous parent + //for (S32 i = 0; i < HISTORY_NUM; i++) + //{ + // mParent->mCountHistory[i] -= mCountHistory[i]; + //} - // subtract average timing from previous parent - mParent->mCountAverage -= mCountAverage; + //// subtract average timing from previous parent + //mParent->mCountAverage -= mCountAverage; - std::vector& children = mParent->getChildren(); - std::vector::iterator found_it = std::find(children.begin(), children.end(), this); + std::vector& children = mParent->getChildren(); + std::vector::iterator found_it = std::find(children.begin(), children.end(), this); if (found_it != children.end()) { children.erase(found_it); @@ -224,10 +220,10 @@ void BlockTimer::setParent(BlockTimer* parent) } } -S32 BlockTimer::getDepth() +S32 TimeBlock::getDepth() { S32 depth = 0; - BlockTimer* timerp = mParent; + TimeBlock* timerp = mParent; while(timerp) { depth++; @@ -238,291 +234,152 @@ S32 BlockTimer::getDepth() } // static -void BlockTimer::processTimes() +void TimeBlock::processTimes() { - if (getCurFrameIndex() < 0) return; - - buildHierarchy(); - accumulateTimings(); -} - -// sort child timers by name -struct SortTimerByName -{ - bool operator()(const BlockTimer* i1, const BlockTimer* i2) - { - return i1->getName() < i2->getName(); - } -}; - -//static -void BlockTimer::buildHierarchy() -{ - if (getCurFrameIndex() < 0 ) return; - - // set up initial tree + //void TimeBlock::buildHierarchy() { - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); it != end_it; ++it) + // set up initial tree { - BlockTimer& timer = *it; - if (&timer == &BlockTimer::getRootTimer()) continue; - - // bootstrap tree construction by attaching to last timer to be on stack - // when this timer was called - if (timer.mParent == &BlockTimer::getRootTimer()) + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); it != end_it; ++it) { - TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + TimeBlock& timer = *it; + if (&timer == &TimeBlock::getRootTimer()) continue; - if (tree_node.mLastCaller) + // bootstrap tree construction by attaching to last timer to be on stack + // when this timer was called + if (timer.mParent == &TimeBlock::getRootTimer()) { - timer.setParent(tree_node.mLastCaller); + TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + + if (tree_node.mLastCaller) + { + timer.setParent(tree_node.mLastCaller); + } + // no need to push up tree on first use, flag can be set spuriously + tree_node.mMoveUpTree = false; } - // no need to push up tree on first use, flag can be set spuriously - tree_node.mMoveUpTree = false; } } - } - - // bump timers up tree if they have been flagged as being in the wrong place - // do this in a bottom up order to promote descendants first before promoting ancestors - // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(BlockTimer::getRootTimer()); - it != end_timer_tree_bottom_up(); - ++it) - { - BlockTimer* timerp = *it; - // skip root timer - if (timerp == &BlockTimer::getRootTimer()) continue; - TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timerp->getIndex()]; - if (tree_node.mMoveUpTree) + // bump timers up tree if they have been flagged as being in the wrong place + // do this in a bottom up order to promote descendants first before promoting ancestors + // this preserves partial order derived from current frame's observations + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); + it != end_timer_tree_bottom_up(); + ++it) { - // since ancestors have already been visited, re-parenting won't affect tree traversal - //step up tree, bringing our descendants with us - LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << - " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; - timerp->setParent(timerp->getParent()->getParent()); - tree_node.mMoveUpTree = false; + TimeBlock* timerp = *it; + // skip root timer + if (timerp == &TimeBlock::getRootTimer()) continue; + TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timerp->getIndex()]; - // don't bubble up any ancestors until descendants are done bubbling up - it.skipAncestors(); - } - } + if (tree_node.mMoveUpTree) + { + // since ancestors have already been visited, re-parenting won't affect tree traversal + //step up tree, bringing our descendants with us + LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << + " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; + timerp->setParent(timerp->getParent()->getParent()); + tree_node.mMoveUpTree = false; - // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(BlockTimer::getRootTimer()); - it != end_timer_tree(); - ++it) - { - BlockTimer* timerp = (*it); - if (timerp->mNeedsSorting) - { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + // don't bubble up any ancestors until descendants are done bubbling up + it.skipAncestors(); + } } - timerp->mNeedsSorting = false; - } -} - -//static -void BlockTimer::accumulateTimings() -{ - U64 cur_time = getCPUClockCount64(); - - // root defined by parent pointing to self - CurTimerData* cur_data = sCurTimerData.get(); - // walk up stack of active timers and accumulate current time while leaving timing structures active - Time* cur_timer = cur_data->mCurTimer; - TimerAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); - while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) - { - U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; - cur_data->mChildTime = 0; - accumulator.mSelfTimeCounter += self_time_delta; - accumulator.mTotalTimeCounter += cumulative_time_delta; - - cur_timer->mStartTime = cur_time; - cur_data = &cur_timer->mLastTimerData; - cur_data->mChildTime += cumulative_time_delta; - if (cur_data->mTimerData) + // sort timers by time last called, so call graph makes sense + for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer()); + it != end_timer_tree(); + ++it) { - accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + TimeBlock* timerp = (*it); + if (timerp->mNeedsSorting) + { + std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + } + timerp->mNeedsSorting = false; } - - cur_timer = cur_timer->mLastTimerData.mCurTimer; } - - // traverse tree in DFS post order, or bottom up - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(BlockTimer::getRootTimer()); - it != end_timer_tree_bottom_up(); - ++it) + + //void TimeBlock::accumulateTimings() { - BlockTimer* timerp = (*it); - TimerAccumulator& accumulator = timerp->getPrimaryAccumulator(); - timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; - for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) - { - timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; - } - - S32 cur_frame = getCurFrameIndex(); - if (cur_frame >= 0) + U64 cur_time = getCPUClockCount64(); + + // root defined by parent pointing to self + CurTimerData* cur_data = sCurTimerData.get(); + // walk up stack of active timers and accumulate current time while leaving timing structures active + BlockTimer* cur_timer = cur_data->mCurTimer; + TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { - // update timer history - int hidx = cur_frame % HISTORY_NUM; + U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; + cur_data->mChildTime = 0; + accumulator.mSelfTimeCounter += self_time_delta; + accumulator.mTotalTimeCounter += cumulative_time_delta; - timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; - timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); - timerp->mCallHistory[hidx] = accumulator.mCalls; - timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + accumulator.mCalls) / (cur_frame+1); - } - } -} + cur_timer->mStartTime = cur_time; -// static -void BlockTimer::resetFrame() -{ - if (sLog) - { //output current frame counts to performance log - - static S32 call_count = 0; - if (call_count % 100 == 0) - { - LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL; - LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; - LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; - } - call_count++; - - F64 iclock_freq = 1000.0 / get_clock_count(); // good place to calculate clock frequency - - F64 total_time = 0; - LLSD sd; - - { - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), - end_it = LLInstanceTracker::endInstances(); - it != end_it; - ++it) + cur_data = &cur_timer->mLastTimerData; + cur_data->mChildTime += cumulative_time_delta; + if (cur_data->mTimerData) { - BlockTimer& timer = *it; - TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); - sd[timer.getName()]["Time"] = (LLSD::Real) (accumulator.mSelfTimeCounter*iclock_freq); - sd[timer.getName()]["Calls"] = (LLSD::Integer) accumulator.mCalls; - - // computing total time here because getting the root timer's getCountHistory - // doesn't work correctly on the first frame - total_time = total_time + accumulator.mSelfTimeCounter * iclock_freq; + accumulator = cur_data->mTimerData->getPrimaryAccumulator(); } - } - sd["Total"]["Time"] = (LLSD::Real) total_time; - sd["Total"]["Calls"] = (LLSD::Integer) 1; - - { - LLMutexLock lock(sLogLock); - sLogQueue.push(sd); + cur_timer = cur_timer->mLastTimerData.mCurTimer; } - } - - // reset for next frame - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), - end_it = LLInstanceTracker::endInstances(); - it != end_it; - ++it) - { - BlockTimer& timer = *it; - TimerAccumulator& accumulator = timer.getPrimaryAccumulator(); - TimerTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; - - accumulator.mSelfTimeCounter = 0; - accumulator.mTotalTimeCounter = 0; - accumulator.mCalls = 0; - tree_node.mLastCaller = NULL; - tree_node.mMoveUpTree = false; - } -} - -//static -void BlockTimer::reset() -{ - resetFrame(); // reset frame data - - // walk up stack of active timers and reset start times to current time - // effectively zeroing out any accumulated time - U64 cur_time = getCPUClockCount64(); - - // root defined by parent pointing to self - CurTimerData* cur_data = sCurTimerData.get(); - Time* cur_timer = cur_data->mCurTimer; - while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) - { - cur_timer->mStartTime = cur_time; - cur_data->mChildTime = 0; - - cur_data = &cur_timer->mLastTimerData; - cur_timer = cur_data->mCurTimer; - } - // reset all history - { - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), - end_it = LLInstanceTracker::endInstances(); - it != end_it; - ++it) - { - BlockTimer& timer = *it; - if (&timer != &BlockTimer::getRootTimer()) - { - timer.setParent(&BlockTimer::getRootTimer()); - } - - timer.mCountAverage = 0; - timer.mCallAverage = 0; - memset(timer.mCountHistory, 0, sizeof(U64) * HISTORY_NUM); - memset(timer.mCallHistory, 0, sizeof(U32) * HISTORY_NUM); - } + // traverse tree in DFS post order, or bottom up + //for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); + // it != end_timer_tree_bottom_up(); + // ++it) + //{ + // TimeBlock* timerp = (*it); + // TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); + // timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; + // for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) + // { + // timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; + // } + + //S32 cur_frame = getCurFrameIndex(); + //if (cur_frame >= 0) + //{ + // // update timer history + + // int hidx = getCurFrameIndex() % HISTORY_NUM; + + // timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; + // timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); + // timerp->mCallHistory[hidx] = accumulator.mCalls; + // timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + accumulator.mCalls) / (cur_frame+1); + //} + //} } - - sLastFrameIndex = 0; - sCurFrameIndex = 0; } -U64 BlockTimer::getHistoricalCount(S32 history_index) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % HISTORY_NUM; - return mCountHistory[history_idx]; -} - -U32 BlockTimer::getHistoricalCalls(S32 history_index ) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % HISTORY_NUM; - return mCallHistory[history_idx]; -} -std::vector::const_iterator BlockTimer::beginChildren() +std::vector::const_iterator TimeBlock::beginChildren() { return mChildren.begin(); } -std::vector::const_iterator BlockTimer::endChildren() +std::vector::const_iterator TimeBlock::endChildren() { return mChildren.end(); } -std::vector& BlockTimer::getChildren() +std::vector& TimeBlock::getChildren() { return mChildren; } //static -void BlockTimer::nextFrame() +void TimeBlock::nextFrame() { get_clock_count(); // good place to calculate clock frequency - U64 frame_time = BlockTimer::getCPUClockCount64(); + U64 frame_time = TimeBlock::getCPUClockCount64(); if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) { llinfos << "Slow frame, fast timers inaccurate" << llendl; @@ -530,31 +387,88 @@ void BlockTimer::nextFrame() if (!sPauseHistory) { - BlockTimer::processTimes(); + TimeBlock::processTimes(); sLastFrameIndex = sCurFrameIndex++; } // get ready for next frame - BlockTimer::resetFrame(); + //void TimeBlock::resetFrame() + { + if (sLog) + { //output current frame counts to performance log + + static S32 call_count = 0; + if (call_count % 100 == 0) + { + LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL; + LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; + LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; + } + call_count++; + + LLUnit total_time = 0; + LLSD sd; + + { + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) + { + TimeBlock& timer = *it; + LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); + sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecordingPeriod().getSum(timer).value()); + sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecordingPeriod().getSum(timer.callCount())); + + // computing total time here because getting the root timer's getCountHistory + // doesn't work correctly on the first frame + total_time += frame_recording.getLastRecordingPeriod().getSum(timer); + } + } + + sd["Total"]["Time"] = (LLSD::Real) total_time.value(); + sd["Total"]["Calls"] = (LLSD::Integer) 1; + + { + LLMutexLock lock(sLogLock); + sLogQueue.push(sd); + } + } + + // reset for next frame + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) + { + TimeBlock& timer = *it; + TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + + tree_node.mLastCaller = NULL; + tree_node.mMoveUpTree = false; + } + } sLastFrameTime = frame_time; } //static -void Time::dumpCurTimes() +void TimeBlock::dumpCurTimes() { // accumulate timings, etc. - BlockTimer::processTimes(); + processTimes(); - F64 clock_freq = (F64)get_clock_count(); - F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds - // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(BlockTimer::getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer()); it != end_timer_tree(); ++it) { - BlockTimer* timerp = (*it); - F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); + LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); + TimeBlock* timerp = (*it); + LLUnit total_time_ms = frame_recording.getLastRecordingPeriod().getSum(*timerp); + U32 num_calls = frame_recording.getLastRecordingPeriod().getSum(timerp->callCount()); + // Don't bother with really brief times, keep output concise if (total_time_ms < 0.1) continue; @@ -564,17 +478,16 @@ void Time::dumpCurTimes() out_str << "\t"; } - out_str << timerp->getName() << " " - << std::setprecision(3) << total_time_ms << " ms, " - << timerp->getHistoricalCalls(0) << " calls"; + << std::setprecision(3) << total_time_ms.as() << " ms, " + << num_calls << " calls"; llinfos << out_str.str() << llendl; } } //static -void Time::writeLog(std::ostream& os) +void TimeBlock::writeLog(std::ostream& os) { while (!sLogQueue.empty()) { @@ -585,29 +498,34 @@ void Time::writeLog(std::ostream& os) } } +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// +// TimeBlockAccumulator +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// -TimerAccumulator::TimerAccumulator() : mSelfTimeCounter(0), +TimeBlockAccumulator::TimeBlockAccumulator() +: mSelfTimeCounter(0), mTotalTimeCounter(0), mCalls(0) {} -void TimerAccumulator::addSamples( const TimerAccumulator& other ) +void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { mSelfTimeCounter += other.mSelfTimeCounter; mTotalTimeCounter += other.mTotalTimeCounter; mCalls += other.mCalls; } -void TimerAccumulator::reset( const TimerAccumulator* other ) +void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) { mTotalTimeCounter = 0; mSelfTimeCounter = 0; mCalls = 0; } -TimerTreeNode::TimerTreeNode() +TimeBlockTreeNode::TimeBlockTreeNode() : mLastCaller(NULL), mActiveCount(0), mMoveUpTree(false) {} -} + +} // namespace LLTrace -- cgit v1.2.3 From c99886d94389babc78e92bbfa5084fdd785915af Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 7 Dec 2012 15:20:12 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system improved unit tests for LLUnit renamed LLUnit to LLUnitImplicit with LLUnit being reserved for explicit units --- indra/llcommon/llfasttimer.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index cf7655acf7..37e0fbac0a 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -166,7 +166,7 @@ U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer firstcall = false; } #endif - return sCPUClockFrequency; + return sCPUClockFrequency.value(); } #endif @@ -408,7 +408,7 @@ void TimeBlock::nextFrame() } call_count++; - LLUnit total_time = 0; + LLUnit total_time(0); LLSD sd; { @@ -479,7 +479,7 @@ void TimeBlock::dumpCurTimes() } out_str << timerp->getName() << " " - << std::setprecision(3) << total_time_ms.as() << " ms, " + << std::setprecision(3) << total_time_ms.as().value() << " ms, " << num_calls << " calls"; llinfos << out_str.str() << llendl; -- cgit v1.2.3 From c219282f5de753a044cecb53bd806145f68add9a Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Tue, 18 Dec 2012 20:07:25 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system removed some potential data races got memory stats recording in trace system --- indra/llcommon/llfasttimer.cpp | 326 ++++++++++++++++++----------------------- 1 file changed, 139 insertions(+), 187 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 37e0fbac0a..f4fa8f1e61 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -59,11 +59,6 @@ namespace LLTrace ////////////////////////////////////////////////////////////////////////////// // statics -S32 TimeBlock::sCurFrameIndex = -1; -S32 TimeBlock::sLastFrameIndex = -1; -U64 TimeBlock::sLastFrameTime = TimeBlock::getCPUClockCount64(); -bool TimeBlock::sPauseHistory = 0; -bool TimeBlock::sResetHistory = 0; bool TimeBlock::sLog = false; std::string TimeBlock::sLogName = ""; bool TimeBlock::sMetricLog = false; @@ -220,143 +215,126 @@ void TimeBlock::setParent(TimeBlock* parent) } } -S32 TimeBlock::getDepth() -{ - S32 depth = 0; - TimeBlock* timerp = mParent; - while(timerp) - { - depth++; - if (timerp->getParent() == timerp) break; - timerp = timerp->mParent; - } - return depth; -} - // static void TimeBlock::processTimes() { - //void TimeBlock::buildHierarchy() + get_clock_count(); // good place to calculate clock frequency + U64 cur_time = getCPUClockCount64(); + CurTimerData* cur_data = sCurTimerData.get(); + + // set up initial tree + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) { - // set up initial tree + TimeBlock& timer = *it; + if (&timer == &TimeBlock::getRootTimer()) continue; + + // bootstrap tree construction by attaching to last timer to be on stack + // when this timer was called + if (timer.mParent == &TimeBlock::getRootTimer()) { - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); it != end_it; ++it) + TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator(); + + if (accumulator.mLastCaller) { - TimeBlock& timer = *it; - if (&timer == &TimeBlock::getRootTimer()) continue; - - // bootstrap tree construction by attaching to last timer to be on stack - // when this timer was called - if (timer.mParent == &TimeBlock::getRootTimer()) - { - TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; - - if (tree_node.mLastCaller) - { - timer.setParent(tree_node.mLastCaller); - } - // no need to push up tree on first use, flag can be set spuriously - tree_node.mMoveUpTree = false; - } + timer.setParent(accumulator.mLastCaller); + accumulator.mParent = accumulator.mLastCaller; } + // no need to push up tree on first use, flag can be set spuriously + accumulator.mMoveUpTree = false; } + } - // bump timers up tree if they have been flagged as being in the wrong place - // do this in a bottom up order to promote descendants first before promoting ancestors - // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); - it != end_timer_tree_bottom_up(); - ++it) + // bump timers up tree if they have been flagged as being in the wrong place + // do this in a bottom up order to promote descendants first before promoting ancestors + // this preserves partial order derived from current frame's observations + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); + it != end_timer_tree_bottom_up(); + ++it) + { + TimeBlock* timerp = *it; + + // sort timers by time last called, so call graph makes sense + if (timerp->mNeedsSorting) { - TimeBlock* timerp = *it; - // skip root timer - if (timerp == &TimeBlock::getRootTimer()) continue; - TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timerp->getIndex()]; + std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + } + + // skip root timer + if (timerp != &TimeBlock::getRootTimer()) + { + TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); - if (tree_node.mMoveUpTree) + if (accumulator.mMoveUpTree) { // since ancestors have already been visited, re-parenting won't affect tree traversal //step up tree, bringing our descendants with us LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; timerp->setParent(timerp->getParent()->getParent()); - tree_node.mMoveUpTree = false; + accumulator.mParent = timerp->mParent; + accumulator.mMoveUpTree = false; // don't bubble up any ancestors until descendants are done bubbling up + // as ancestors may call this timer only on certain paths, so we want to resolve + // child-most block locations before their parents it.skipAncestors(); } } - - // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer()); - it != end_timer_tree(); - ++it) - { - TimeBlock* timerp = (*it); - if (timerp->mNeedsSorting) - { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); - } - timerp->mNeedsSorting = false; - } } - - //void TimeBlock::accumulateTimings() - { - U64 cur_time = getCPUClockCount64(); - - // root defined by parent pointing to self - CurTimerData* cur_data = sCurTimerData.get(); - // walk up stack of active timers and accumulate current time while leaving timing structures active - BlockTimer* cur_timer = cur_data->mCurTimer; - TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); - while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) - { - U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; - cur_data->mChildTime = 0; - accumulator.mSelfTimeCounter += self_time_delta; - accumulator.mTotalTimeCounter += cumulative_time_delta; - cur_timer->mStartTime = cur_time; + // walk up stack of active timers and accumulate current time while leaving timing structures active + BlockTimer* cur_timer = cur_data->mCurTimer; + TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + // root defined by parent pointing to self + while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) + { + U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; + cur_data->mChildTime = 0; + accumulator.mSelfTimeCounter += self_time_delta; + accumulator.mTotalTimeCounter += cumulative_time_delta; - cur_data = &cur_timer->mLastTimerData; - cur_data->mChildTime += cumulative_time_delta; - if (cur_data->mTimerData) - { - accumulator = cur_data->mTimerData->getPrimaryAccumulator(); - } + cur_timer->mStartTime = cur_time; - cur_timer = cur_timer->mLastTimerData.mCurTimer; + cur_data = &cur_timer->mLastTimerData; + cur_data->mChildTime += cumulative_time_delta; + if (cur_data->mTimerData) + { + accumulator = cur_data->mTimerData->getPrimaryAccumulator(); } - // traverse tree in DFS post order, or bottom up - //for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); - // it != end_timer_tree_bottom_up(); - // ++it) - //{ - // TimeBlock* timerp = (*it); - // TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); - // timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; - // for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) - // { - // timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; - // } - - //S32 cur_frame = getCurFrameIndex(); - //if (cur_frame >= 0) - //{ - // // update timer history + cur_timer = cur_timer->mLastTimerData.mCurTimer; + } - // int hidx = getCurFrameIndex() % HISTORY_NUM; - // timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter; - // timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1); - // timerp->mCallHistory[hidx] = accumulator.mCalls; - // timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + accumulator.mCalls) / (cur_frame+1); - //} - //} + // reset for next frame + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) + { + TimeBlock& timer = *it; + TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator(); + + accumulator.mLastCaller = NULL; + accumulator.mMoveUpTree = false; } + + // traverse tree in DFS post order, or bottom up + //for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); + // it != end_timer_tree_bottom_up(); + // ++it) + //{ + // TimeBlock* timerp = (*it); + // TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); + // timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; + // for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) + // { + // timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; + // } + //} } @@ -376,106 +354,78 @@ std::vector& TimeBlock::getChildren() } //static -void TimeBlock::nextFrame() +void TimeBlock::logStats() { - get_clock_count(); // good place to calculate clock frequency - U64 frame_time = TimeBlock::getCPUClockCount64(); - if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) - { - llinfos << "Slow frame, fast timers inaccurate" << llendl; - } - - if (!sPauseHistory) - { - TimeBlock::processTimes(); - sLastFrameIndex = sCurFrameIndex++; - } - // get ready for next frame - //void TimeBlock::resetFrame() - { - if (sLog) - { //output current frame counts to performance log + if (sLog) + { //output current frame counts to performance log - static S32 call_count = 0; - if (call_count % 100 == 0) - { - LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL; - LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; - LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; - } - call_count++; + static S32 call_count = 0; + if (call_count % 100 == 0) + { + LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL; + LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; + LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; + } + call_count++; - LLUnit total_time(0); - LLSD sd; + LLUnit total_time(0); + LLSD sd; + { + for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), + end_it = LLInstanceTracker::endInstances(); + it != end_it; + ++it) { - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), - end_it = LLInstanceTracker::endInstances(); - it != end_it; - ++it) - { - TimeBlock& timer = *it; - LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); - sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecordingPeriod().getSum(timer).value()); - sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecordingPeriod().getSum(timer.callCount())); - - // computing total time here because getting the root timer's getCountHistory - // doesn't work correctly on the first frame - total_time += frame_recording.getLastRecordingPeriod().getSum(timer); - } - } - - sd["Total"]["Time"] = (LLSD::Real) total_time.value(); - sd["Total"]["Calls"] = (LLSD::Integer) 1; + TimeBlock& timer = *it; + LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); + sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecordingPeriod().getSum(timer).value()); + sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecordingPeriod().getSum(timer.callCount())); - { - LLMutexLock lock(sLogLock); - sLogQueue.push(sd); + // computing total time here because getting the root timer's getCountHistory + // doesn't work correctly on the first frame + total_time += frame_recording.getLastRecordingPeriod().getSum(timer); } } - // reset for next frame - for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), - end_it = LLInstanceTracker::endInstances(); - it != end_it; - ++it) - { - TimeBlock& timer = *it; - TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()]; + sd["Total"]["Time"] = (LLSD::Real) total_time.value(); + sd["Total"]["Calls"] = (LLSD::Integer) 1; - tree_node.mLastCaller = NULL; - tree_node.mMoveUpTree = false; + { + LLMutexLock lock(sLogLock); + sLogQueue.push(sd); } } - sLastFrameTime = frame_time; + } //static void TimeBlock::dumpCurTimes() { - // accumulate timings, etc. - processTimes(); - + LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); + LLTrace::Recording& last_frame_recording = frame_recording.getLastRecordingPeriod(); + // walk over timers in depth order and output timings for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer()); it != end_timer_tree(); ++it) { - LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); TimeBlock* timerp = (*it); - LLUnit total_time_ms = frame_recording.getLastRecordingPeriod().getSum(*timerp); - U32 num_calls = frame_recording.getLastRecordingPeriod().getSum(timerp->callCount()); + LLUnit total_time_ms = last_frame_recording.getSum(*timerp); + U32 num_calls = last_frame_recording.getSum(timerp->callCount()); // Don't bother with really brief times, keep output concise if (total_time_ms < 0.1) continue; std::ostringstream out_str; - for (S32 i = 0; i < timerp->getDepth(); i++) + TimeBlock* parent_timerp = timerp; + while(parent_timerp && parent_timerp != parent_timerp->getParent()) { out_str << "\t"; + parent_timerp = parent_timerp->getParent(); } out_str << timerp->getName() << " " @@ -505,7 +455,11 @@ void TimeBlock::writeLog(std::ostream& os) TimeBlockAccumulator::TimeBlockAccumulator() : mSelfTimeCounter(0), mTotalTimeCounter(0), - mCalls(0) + mCalls(0), + mLastCaller(NULL), + mActiveCount(0), + mMoveUpTree(false), + mParent(NULL) {} void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) @@ -513,6 +467,10 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) mSelfTimeCounter += other.mSelfTimeCounter; mTotalTimeCounter += other.mTotalTimeCounter; mCalls += other.mCalls; + mLastCaller = other.mLastCaller; + mActiveCount = other.mActiveCount; + mMoveUpTree = other.mMoveUpTree; + mParent = other.mParent; } void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) @@ -522,10 +480,4 @@ void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) mCalls = 0; } -TimeBlockTreeNode::TimeBlockTreeNode() -: mLastCaller(NULL), - mActiveCount(0), - mMoveUpTree(false) -{} - } // namespace LLTrace -- cgit v1.2.3 From 013f04cabec8e110ee659d9b3f75a4d25f114b7b Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 21 Dec 2012 00:13:21 -0800 Subject: SH-3468 WIP add memory tracking base class improvements on lifetime of lltrace core data structures tweaks to thread local pointer handling so that static constructors/destructors can safely call functions that use lltrace --- indra/llcommon/llfasttimer.cpp | 93 +++++++++++++----------------------------- 1 file changed, 29 insertions(+), 64 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index f4fa8f1e61..7c90b946af 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -35,6 +35,7 @@ #include "llunit.h" #include "llsd.h" #include "lltracerecording.h" +#include "lltracethreadrecorder.h" #include #include @@ -167,52 +168,16 @@ U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer TimeBlock::TimeBlock(const char* name, bool open, TimeBlock* parent) : TraceType(name), - mCollapsed(true), - mParent(NULL), - mNeedsSorting(false) + mCollapsed(true) { setCollapsed(!open); - - if (parent) - { - setParent(parent); - } - else - { - mParent = this; - } } -void TimeBlock::setParent(TimeBlock* parent) +TimeBlockTreeNode& TimeBlock::getTreeNode() const { - llassert_always(parent != this); - llassert_always(parent != NULL); - - if (mParent) - { - //// subtract our accumulated from previous parent - //for (S32 i = 0; i < HISTORY_NUM; i++) - //{ - // mParent->mCountHistory[i] -= mCountHistory[i]; - //} - - //// subtract average timing from previous parent - //mParent->mCountAverage -= mCountAverage; - - std::vector& children = mParent->getChildren(); - std::vector::iterator found_it = std::find(children.begin(), children.end(), this); - if (found_it != children.end()) - { - children.erase(found_it); - } - } - - mParent = parent; - if (parent) - { - parent->getChildren().push_back(this); - parent->mNeedsSorting = true; - } + TimeBlockTreeNode* nodep = LLTrace::get_thread_recorder()->getTimeBlockTreeNode(getIndex()); + llassert(nodep); + return *nodep; } // static @@ -232,17 +197,17 @@ void TimeBlock::processTimes() // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.mParent == &TimeBlock::getRootTimer()) + if (timer.getParent() == &TimeBlock::getRootTimer()) { - TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator(); + TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - if (accumulator.mLastCaller) + if (accumulator->mLastCaller) { - timer.setParent(accumulator.mLastCaller); - accumulator.mParent = accumulator.mLastCaller; + timer.setParent(accumulator->mLastCaller); + accumulator->mParent = accumulator->mLastCaller; } // no need to push up tree on first use, flag can be set spuriously - accumulator.mMoveUpTree = false; + accumulator->mMoveUpTree = false; } } @@ -256,25 +221,25 @@ void TimeBlock::processTimes() TimeBlock* timerp = *it; // sort timers by time last called, so call graph makes sense - if (timerp->mNeedsSorting) + if (timerp->getTreeNode().mNeedsSorting) { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + std::sort(timerp->beginChildren(), timerp->endChildren(), SortTimerByName()); } // skip root timer if (timerp != &TimeBlock::getRootTimer()) { - TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); + TimeBlockAccumulator* accumulator = timerp->getPrimaryAccumulator(); - if (accumulator.mMoveUpTree) + if (accumulator->mMoveUpTree) { // since ancestors have already been visited, re-parenting won't affect tree traversal //step up tree, bringing our descendants with us LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; timerp->setParent(timerp->getParent()->getParent()); - accumulator.mParent = timerp->mParent; - accumulator.mMoveUpTree = false; + accumulator->mParent = timerp->getParent(); + accumulator->mMoveUpTree = false; // don't bubble up any ancestors until descendants are done bubbling up // as ancestors may call this timer only on certain paths, so we want to resolve @@ -286,15 +251,15 @@ void TimeBlock::processTimes() // walk up stack of active timers and accumulate current time while leaving timing structures active BlockTimer* cur_timer = cur_data->mCurTimer; - TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + TimeBlockAccumulator* accumulator = cur_data->mTimerData->getPrimaryAccumulator(); // root defined by parent pointing to self while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; cur_data->mChildTime = 0; - accumulator.mSelfTimeCounter += self_time_delta; - accumulator.mTotalTimeCounter += cumulative_time_delta; + accumulator->mSelfTimeCounter += self_time_delta; + accumulator->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; @@ -316,10 +281,10 @@ void TimeBlock::processTimes() ++it) { TimeBlock& timer = *it; - TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator(); + TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - accumulator.mLastCaller = NULL; - accumulator.mMoveUpTree = false; + accumulator->mLastCaller = NULL; + accumulator->mMoveUpTree = false; } // traverse tree in DFS post order, or bottom up @@ -338,19 +303,19 @@ void TimeBlock::processTimes() } -std::vector::const_iterator TimeBlock::beginChildren() +std::vector::iterator TimeBlock::beginChildren() { - return mChildren.begin(); + return getTreeNode().mChildren.begin(); } -std::vector::const_iterator TimeBlock::endChildren() +std::vector::iterator TimeBlock::endChildren() { - return mChildren.end(); + return getTreeNode().mChildren.end(); } std::vector& TimeBlock::getChildren() { - return mChildren; + return getTreeNode().mChildren; } //static -- cgit v1.2.3 From cda2cdda511eb2f7a58e284db2c852fd4a3808ae Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 3 Jan 2013 00:30:54 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system made fast timer stack thread local added LLThreadLocalSingleton made LLThreadLocalPointer obey pointer rules for const added LLThreadLocalSingletonPointer for fast thread local pointers --- indra/llcommon/llfasttimer.cpp | 41 ++++++++++++++++++++--------------------- 1 file changed, 20 insertions(+), 21 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 7c90b946af..ad8cf7296e 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -70,8 +70,6 @@ U64 TimeBlock::sClockResolution = 1000000000; // Nanosecond resolution U64 TimeBlock::sClockResolution = 1000000; // Microsecond resolution #endif -LLThreadLocalPointer TimeBlock::sCurTimerData; - static LLMutex* sLogLock = NULL; static std::queue sLogQueue; @@ -118,7 +116,7 @@ struct SortTimerByName } }; -TimeBlock& TimeBlock::getRootTimer() +TimeBlock& TimeBlock::getRootTimeBlock() { static TimeBlock root_timer("root", true, NULL); return root_timer; @@ -185,7 +183,7 @@ void TimeBlock::processTimes() { get_clock_count(); // good place to calculate clock frequency U64 cur_time = getCPUClockCount64(); - CurTimerData* cur_data = sCurTimerData.get(); + BlockTimerStackRecord* stack_record = ThreadTimerStack::getInstance(); // set up initial tree for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); @@ -193,11 +191,11 @@ void TimeBlock::processTimes() ++it) { TimeBlock& timer = *it; - if (&timer == &TimeBlock::getRootTimer()) continue; + if (&timer == &TimeBlock::getRootTimeBlock()) continue; // bootstrap tree construction by attaching to last timer to be on stack // when this timer was called - if (timer.getParent() == &TimeBlock::getRootTimer()) + if (timer.getParent() == &TimeBlock::getRootTimeBlock()) { TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); @@ -214,20 +212,21 @@ void TimeBlock::processTimes() // bump timers up tree if they have been flagged as being in the wrong place // do this in a bottom up order to promote descendants first before promoting ancestors // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimeBlock()); it != end_timer_tree_bottom_up(); ++it) { TimeBlock* timerp = *it; // sort timers by time last called, so call graph makes sense - if (timerp->getTreeNode().mNeedsSorting) + TimeBlockTreeNode& tree_node = timerp->getTreeNode(); + if (tree_node.mNeedsSorting) { - std::sort(timerp->beginChildren(), timerp->endChildren(), SortTimerByName()); + std::sort(tree_node.mChildren.begin(), tree_node.mChildren.end(), SortTimerByName()); } // skip root timer - if (timerp != &TimeBlock::getRootTimer()) + if (timerp != &TimeBlock::getRootTimeBlock()) { TimeBlockAccumulator* accumulator = timerp->getPrimaryAccumulator(); @@ -250,27 +249,27 @@ void TimeBlock::processTimes() } // walk up stack of active timers and accumulate current time while leaving timing structures active - BlockTimer* cur_timer = cur_data->mCurTimer; - TimeBlockAccumulator* accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + BlockTimer* cur_timer = stack_record->mActiveTimer; + TimeBlockAccumulator* accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); // root defined by parent pointing to self - while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) + while(cur_timer && cur_timer->mLastTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime; - cur_data->mChildTime = 0; + U64 self_time_delta = cumulative_time_delta - stack_record->mChildTime; + stack_record->mChildTime = 0; accumulator->mSelfTimeCounter += self_time_delta; accumulator->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; - cur_data = &cur_timer->mLastTimerData; - cur_data->mChildTime += cumulative_time_delta; - if (cur_data->mTimerData) + stack_record = &cur_timer->mLastTimerData; + stack_record->mChildTime += cumulative_time_delta; + if (stack_record->mTimeBlock) { - accumulator = cur_data->mTimerData->getPrimaryAccumulator(); + accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); } - cur_timer = cur_timer->mLastTimerData.mCurTimer; + cur_timer = cur_timer->mLastTimerData.mActiveTimer; } @@ -374,7 +373,7 @@ void TimeBlock::dumpCurTimes() LLTrace::Recording& last_frame_recording = frame_recording.getLastRecordingPeriod(); // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimeBlock()); it != end_timer_tree(); ++it) { -- cgit v1.2.3 From cf8fa1a958f8676a0911bac7bdb950a865b58c83 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 4 Jan 2013 15:57:28 -0800 Subject: SH-3468 WIP add memory tracking base class further compile error fixes --- indra/llcommon/llfasttimer.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index ad8cf7296e..e6233a094e 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -137,12 +137,12 @@ void TimeBlock::setLogLock(LLMutex* lock) //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer +U64 TimeBlock::countsPerSecond() { return sClockResolution; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer +U64 TimeBlock::countsPerSecond() { #if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz @@ -165,7 +165,7 @@ U64 TimeBlock::countsPerSecond() // counts per second for the *64-bit* timer #endif TimeBlock::TimeBlock(const char* name, bool open, TimeBlock* parent) -: TraceType(name), +: TraceType(name), mCollapsed(true) { setCollapsed(!open); -- cgit v1.2.3 From 20b2fa4052ae6789ec8894f33f4764a1f7233b24 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 14 Jan 2013 23:08:01 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system improved performance of fast timer stat gathering --- indra/llcommon/llfasttimer.cpp | 28 ++++++++++++++-------------- 1 file changed, 14 insertions(+), 14 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e6233a094e..37332da31c 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -199,10 +199,11 @@ void TimeBlock::processTimes() { TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - if (accumulator->mLastCaller) + if (accumulator->mLastAccumulator) { - timer.setParent(accumulator->mLastCaller); - accumulator->mParent = accumulator->mLastCaller; + TimeBlock* parent = accumulator->mLastAccumulator->mBlock; + timer.setParent(parent); + accumulator->mParent = parent; } // no need to push up tree on first use, flag can be set spuriously accumulator->mMoveUpTree = false; @@ -250,23 +251,22 @@ void TimeBlock::processTimes() // walk up stack of active timers and accumulate current time while leaving timing structures active BlockTimer* cur_timer = stack_record->mActiveTimer; - TimeBlockAccumulator* accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); + TimeBlockAccumulator* accumulator = stack_record->mAccumulator; // root defined by parent pointing to self while(cur_timer && cur_timer->mLastTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U64 self_time_delta = cumulative_time_delta - stack_record->mChildTime; + accumulator->mChildTimeCounter += stack_record->mChildTime; stack_record->mChildTime = 0; - accumulator->mSelfTimeCounter += self_time_delta; accumulator->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; stack_record = &cur_timer->mLastTimerData; stack_record->mChildTime += cumulative_time_delta; - if (stack_record->mTimeBlock) + if (stack_record->mAccumulator) { - accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); + accumulator = stack_record->mAccumulator; } cur_timer = cur_timer->mLastTimerData.mActiveTimer; @@ -282,7 +282,7 @@ void TimeBlock::processTimes() TimeBlock& timer = *it; TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - accumulator->mLastCaller = NULL; + accumulator->mLastAccumulator = NULL; accumulator->mMoveUpTree = false; } @@ -417,10 +417,10 @@ void TimeBlock::writeLog(std::ostream& os) ////////////////////////////////////////////////////////////////////////////////////////////////////////////////// TimeBlockAccumulator::TimeBlockAccumulator() -: mSelfTimeCounter(0), +: mChildTimeCounter(0), mTotalTimeCounter(0), mCalls(0), - mLastCaller(NULL), + mLastAccumulator(NULL), mActiveCount(0), mMoveUpTree(false), mParent(NULL) @@ -428,10 +428,10 @@ TimeBlockAccumulator::TimeBlockAccumulator() void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { - mSelfTimeCounter += other.mSelfTimeCounter; + mChildTimeCounter += other.mChildTimeCounter; mTotalTimeCounter += other.mTotalTimeCounter; mCalls += other.mCalls; - mLastCaller = other.mLastCaller; + mLastAccumulator = other.mLastAccumulator; mActiveCount = other.mActiveCount; mMoveUpTree = other.mMoveUpTree; mParent = other.mParent; @@ -440,7 +440,7 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) { mTotalTimeCounter = 0; - mSelfTimeCounter = 0; + mChildTimeCounter = 0; mCalls = 0; } -- cgit v1.2.3 From 43a92d01afdb4f1dd4003059b79f87e9687527a1 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 17 Jan 2013 20:11:43 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system fixed some uninitialized variables root timer accumulator was being initialized to NULL --- indra/llcommon/llfasttimer.cpp | 30 +++++++++++++++++------------- 1 file changed, 17 insertions(+), 13 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 37332da31c..b4a422816e 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -183,7 +183,6 @@ void TimeBlock::processTimes() { get_clock_count(); // good place to calculate clock frequency U64 cur_time = getCPUClockCount64(); - BlockTimerStackRecord* stack_record = ThreadTimerStack::getInstance(); // set up initial tree for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); @@ -202,6 +201,7 @@ void TimeBlock::processTimes() if (accumulator->mLastAccumulator) { TimeBlock* parent = accumulator->mLastAccumulator->mBlock; + llassert(parent); timer.setParent(parent); accumulator->mParent = parent; } @@ -250,26 +250,28 @@ void TimeBlock::processTimes() } // walk up stack of active timers and accumulate current time while leaving timing structures active - BlockTimer* cur_timer = stack_record->mActiveTimer; - TimeBlockAccumulator* accumulator = stack_record->mAccumulator; + BlockTimerStackRecord* stack_record = ThreadTimerStack::getInstance(); + BlockTimer* cur_timer = stack_record->mActiveTimer; + TimeBlockAccumulator* accumulator = stack_record->mAccumulator; + + llassert(accumulator); + // root defined by parent pointing to self - while(cur_timer && cur_timer->mLastTimerData.mActiveTimer != cur_timer) + while(cur_timer && cur_timer->mParentTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + + accumulator->mTotalTimeCounter += cumulative_time_delta; accumulator->mChildTimeCounter += stack_record->mChildTime; stack_record->mChildTime = 0; - accumulator->mTotalTimeCounter += cumulative_time_delta; cur_timer->mStartTime = cur_time; - stack_record = &cur_timer->mLastTimerData; - stack_record->mChildTime += cumulative_time_delta; - if (stack_record->mAccumulator) - { - accumulator = stack_record->mAccumulator; - } + stack_record = &cur_timer->mParentTimerData; + accumulator = stack_record->mAccumulator; + cur_timer = stack_record->mActiveTimer; - cur_timer = cur_timer->mLastTimerData.mActiveTimer; + stack_record->mChildTime += cumulative_time_delta; } @@ -423,7 +425,8 @@ TimeBlockAccumulator::TimeBlockAccumulator() mLastAccumulator(NULL), mActiveCount(0), mMoveUpTree(false), - mParent(NULL) + mParent(NULL), + mBlock(NULL) {} void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) @@ -435,6 +438,7 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) mActiveCount = other.mActiveCount; mMoveUpTree = other.mMoveUpTree; mParent = other.mParent; + mBlock = other.mBlock; } void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) -- cgit v1.2.3 From e975ae35ab57f56adfaed64bc108240a5013f040 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 18 Jan 2013 15:59:16 -0800 Subject: SH-3406 WIP convert fast timers to lltrace system fixed crash on startup --- indra/llcommon/llfasttimer.cpp | 26 ++++++++++---------------- 1 file changed, 10 insertions(+), 16 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index b4a422816e..ea4e1a89a2 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -198,12 +198,10 @@ void TimeBlock::processTimes() { TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - if (accumulator->mLastAccumulator) + if (accumulator->mLastCaller) { - TimeBlock* parent = accumulator->mLastAccumulator->mBlock; - llassert(parent); - timer.setParent(parent); - accumulator->mParent = parent; + timer.setParent(accumulator->mLastCaller); + accumulator->mParent = accumulator->mLastCaller; } // no need to push up tree on first use, flag can be set spuriously accumulator->mMoveUpTree = false; @@ -252,10 +250,8 @@ void TimeBlock::processTimes() // walk up stack of active timers and accumulate current time while leaving timing structures active BlockTimerStackRecord* stack_record = ThreadTimerStack::getInstance(); BlockTimer* cur_timer = stack_record->mActiveTimer; - TimeBlockAccumulator* accumulator = stack_record->mAccumulator; - - llassert(accumulator); - + TimeBlockAccumulator* accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); + // root defined by parent pointing to self while(cur_timer && cur_timer->mParentTimerData.mActiveTimer != cur_timer) { @@ -268,7 +264,7 @@ void TimeBlock::processTimes() cur_timer->mStartTime = cur_time; stack_record = &cur_timer->mParentTimerData; - accumulator = stack_record->mAccumulator; + accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); cur_timer = stack_record->mActiveTimer; stack_record->mChildTime += cumulative_time_delta; @@ -284,7 +280,7 @@ void TimeBlock::processTimes() TimeBlock& timer = *it; TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - accumulator->mLastAccumulator = NULL; + accumulator->mLastCaller = NULL; accumulator->mMoveUpTree = false; } @@ -422,11 +418,10 @@ TimeBlockAccumulator::TimeBlockAccumulator() : mChildTimeCounter(0), mTotalTimeCounter(0), mCalls(0), - mLastAccumulator(NULL), + mLastCaller(NULL), mActiveCount(0), mMoveUpTree(false), - mParent(NULL), - mBlock(NULL) + mParent(NULL) {} void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) @@ -434,11 +429,10 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) mChildTimeCounter += other.mChildTimeCounter; mTotalTimeCounter += other.mTotalTimeCounter; mCalls += other.mCalls; - mLastAccumulator = other.mLastAccumulator; + mLastCaller = other.mLastCaller; mActiveCount = other.mActiveCount; mMoveUpTree = other.mMoveUpTree; mParent = other.mParent; - mBlock = other.mBlock; } void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) -- cgit v1.2.3 From 3a555a2ff84d9b340e33673d7a03f37c966f06e6 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 24 Jan 2013 19:53:17 -0800 Subject: SH-3275 WIP interesting Update viewer metrics system to be more flexible removed LLFastTimerView::getFrameTimer() dead code elimination fixed off by one array access crash --- indra/llcommon/llfasttimer.cpp | 15 --------------- 1 file changed, 15 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index ea4e1a89a2..a144a8c94e 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -270,7 +270,6 @@ void TimeBlock::processTimes() stack_record->mChildTime += cumulative_time_delta; } - // reset for next frame for (LLInstanceTracker::instance_iter it = LLInstanceTracker::beginInstances(), end_it = LLInstanceTracker::endInstances(); @@ -283,20 +282,6 @@ void TimeBlock::processTimes() accumulator->mLastCaller = NULL; accumulator->mMoveUpTree = false; } - - // traverse tree in DFS post order, or bottom up - //for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer()); - // it != end_timer_tree_bottom_up(); - // ++it) - //{ - // TimeBlock* timerp = (*it); - // TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator(); - // timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter; - // for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) - // { - // timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; - // } - //} } -- cgit v1.2.3 From 2c68d5367c5c44aceb4ff23d9672c35642e030f7 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Sun, 27 Jan 2013 21:35:20 -0800 Subject: SH-3275 WIP interesting Update viewer metrics system to be more flexible fixed memory leak fixed glitching of fast timer display --- indra/llcommon/llfasttimer.cpp | 7 +++++++ 1 file changed, 7 insertions(+) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index a144a8c94e..e58c5c0f98 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -425,6 +425,13 @@ void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) mTotalTimeCounter = 0; mChildTimeCounter = 0; mCalls = 0; + if (other) + { + mLastCaller = other->mLastCaller; + mActiveCount = other->mActiveCount; + mMoveUpTree = other->mMoveUpTree; + mParent = other->mParent; + } } } // namespace LLTrace -- cgit v1.2.3 From 438cbfe489cc34261ac600bbb22983164e59b1d9 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 7 Feb 2013 20:07:31 -0800 Subject: SH-3275 WIP interesting Update viewer metrics system to be more flexible fix for timings for recursive fast timers not being correct --- indra/llcommon/llfasttimer.cpp | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e58c5c0f98..809a0ef4bf 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -257,8 +257,8 @@ void TimeBlock::processTimes() { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - accumulator->mTotalTimeCounter += cumulative_time_delta; - accumulator->mChildTimeCounter += stack_record->mChildTime; + accumulator->mChildTimeCounter += stack_record->mChildTime - (accumulator->mSelfTimeCounter - cur_timer->mStartSelfTimeCount); + accumulator->mSelfTimeCounter += cumulative_time_delta - stack_record->mChildTime; stack_record->mChildTime = 0; cur_timer->mStartTime = cur_time; @@ -401,7 +401,7 @@ void TimeBlock::writeLog(std::ostream& os) TimeBlockAccumulator::TimeBlockAccumulator() : mChildTimeCounter(0), - mTotalTimeCounter(0), + mSelfTimeCounter(0), mCalls(0), mLastCaller(NULL), mActiveCount(0), @@ -412,7 +412,7 @@ TimeBlockAccumulator::TimeBlockAccumulator() void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { mChildTimeCounter += other.mChildTimeCounter; - mTotalTimeCounter += other.mTotalTimeCounter; + mSelfTimeCounter += other.mSelfTimeCounter; mCalls += other.mCalls; mLastCaller = other.mLastCaller; mActiveCount = other.mActiveCount; @@ -422,7 +422,7 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) { - mTotalTimeCounter = 0; + mSelfTimeCounter = 0; mChildTimeCounter = 0; mCalls = 0; if (other) -- cgit v1.2.3 From e3700112f313f3570887047d5b56a661af0afac5 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Fri, 8 Feb 2013 00:03:31 -0800 Subject: SH-3275 WIP interesting Update viewer metrics system to be more flexible added debug output to BlockTimer --- indra/llcommon/llfasttimer.cpp | 8 ++++++++ 1 file changed, 8 insertions(+) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index e58c5c0f98..ba626bcc32 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -434,4 +434,12 @@ void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) } } +LLUnit BlockTimer::getElapsedTime() +{ + U64 total_time = TimeBlock::getCPUClockCount64() - mStartTime; + + return (F64)total_time / (F64)TimeBlock::countsPerSecond(); +} + + } // namespace LLTrace -- cgit v1.2.3 From 2e15e8fd4ba62204c76f6e2a91d3e50f62e6c1fc Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Sat, 9 Feb 2013 00:34:59 -0800 Subject: SH-3275 FIX interesting Update viewer metrics system to be more flexible fixed anamolous LLFastTimer timings --- indra/llcommon/llfasttimer.cpp | 28 +++++++++++++++++++++------- 1 file changed, 21 insertions(+), 7 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 4387218f5a..0ea91d7e51 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -256,12 +256,16 @@ void TimeBlock::processTimes() while(cur_timer && cur_timer->mParentTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - - accumulator->mChildTimeCounter += stack_record->mChildTime - (accumulator->mSelfTimeCounter - cur_timer->mStartSelfTimeCount); - accumulator->mSelfTimeCounter += cumulative_time_delta - stack_record->mChildTime; + U64 child_time = stack_record->mChildTime + - (accumulator->mSelfTimeCounter - cur_timer->mStartSelfTimeCounter) + - (accumulator->mChildTimeCounter - cur_timer->mStartChildTimeCounter); + accumulator->mChildTimeCounter += child_time; + accumulator->mSelfTimeCounter += cumulative_time_delta - child_time; stack_record->mChildTime = 0; cur_timer->mStartTime = cur_time; + cur_timer->mStartSelfTimeCounter = accumulator->mSelfTimeCounter; + cur_timer->mStartChildTimeCounter = accumulator->mChildTimeCounter; stack_record = &cur_timer->mParentTimerData; accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); @@ -402,6 +406,8 @@ void TimeBlock::writeLog(std::ostream& os) TimeBlockAccumulator::TimeBlockAccumulator() : mChildTimeCounter(0), mSelfTimeCounter(0), + mStartChildTimeCounter(0), + mStartSelfTimeCounter(0), mCalls(0), mLastCaller(NULL), mActiveCount(0), @@ -411,8 +417,8 @@ TimeBlockAccumulator::TimeBlockAccumulator() void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { - mChildTimeCounter += other.mChildTimeCounter; - mSelfTimeCounter += other.mSelfTimeCounter; + mChildTimeCounter += other.mChildTimeCounter - other.mStartChildTimeCounter; + mSelfTimeCounter += other.mSelfTimeCounter - other.mStartSelfTimeCounter; mCalls += other.mCalls; mLastCaller = other.mLastCaller; mActiveCount = other.mActiveCount; @@ -422,16 +428,24 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) { - mSelfTimeCounter = 0; - mChildTimeCounter = 0; mCalls = 0; if (other) { + mStartSelfTimeCounter = other->mSelfTimeCounter; + mSelfTimeCounter = mStartSelfTimeCounter; + mStartChildTimeCounter = other->mChildTimeCounter; + mChildTimeCounter = mStartChildTimeCounter; + mLastCaller = other->mLastCaller; mActiveCount = other->mActiveCount; mMoveUpTree = other->mMoveUpTree; mParent = other->mParent; } + else + { + mStartSelfTimeCounter = mSelfTimeCounter; + mStartChildTimeCounter = mChildTimeCounter; + } } LLUnit BlockTimer::getElapsedTime() -- cgit v1.2.3 From 67ac6e7a294bd7401c55ed1d7423166dda1c0ee6 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Sun, 10 Feb 2013 23:53:45 -0800 Subject: SH-3275 FIX interesting Update viewer metrics system to be more flexible streamlined fast timer delta tracking --- indra/llcommon/llfasttimer.cpp | 30 ++++++++++++------------------ 1 file changed, 12 insertions(+), 18 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 0ea91d7e51..f8837a7085 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -256,16 +256,12 @@ void TimeBlock::processTimes() while(cur_timer && cur_timer->mParentTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U64 child_time = stack_record->mChildTime - - (accumulator->mSelfTimeCounter - cur_timer->mStartSelfTimeCounter) - - (accumulator->mChildTimeCounter - cur_timer->mStartChildTimeCounter); - accumulator->mChildTimeCounter += child_time; - accumulator->mSelfTimeCounter += cumulative_time_delta - child_time; + accumulator->mTotalTimeCounter += cumulative_time_delta - (accumulator->mTotalTimeCounter - accumulator->mStartTotalTimeCounter); + accumulator->mSelfTimeCounter += cumulative_time_delta - stack_record->mChildTime; stack_record->mChildTime = 0; cur_timer->mStartTime = cur_time; - cur_timer->mStartSelfTimeCounter = accumulator->mSelfTimeCounter; - cur_timer->mStartChildTimeCounter = accumulator->mChildTimeCounter; + cur_timer->mStartTotalTimeCounter = accumulator->mTotalTimeCounter; stack_record = &cur_timer->mParentTimerData; accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); @@ -404,10 +400,9 @@ void TimeBlock::writeLog(std::ostream& os) ////////////////////////////////////////////////////////////////////////////////////////////////////////////////// TimeBlockAccumulator::TimeBlockAccumulator() -: mChildTimeCounter(0), +: mTotalTimeCounter(0), mSelfTimeCounter(0), - mStartChildTimeCounter(0), - mStartSelfTimeCounter(0), + mStartTotalTimeCounter(0), mCalls(0), mLastCaller(NULL), mActiveCount(0), @@ -417,8 +412,8 @@ TimeBlockAccumulator::TimeBlockAccumulator() void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { - mChildTimeCounter += other.mChildTimeCounter - other.mStartChildTimeCounter; - mSelfTimeCounter += other.mSelfTimeCounter - other.mStartSelfTimeCounter; + mTotalTimeCounter += other.mTotalTimeCounter - other.mStartTotalTimeCounter; + mSelfTimeCounter += other.mSelfTimeCounter; mCalls += other.mCalls; mLastCaller = other.mLastCaller; mActiveCount = other.mActiveCount; @@ -429,12 +424,12 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) { mCalls = 0; + mSelfTimeCounter = 0; + if (other) { - mStartSelfTimeCounter = other->mSelfTimeCounter; - mSelfTimeCounter = mStartSelfTimeCounter; - mStartChildTimeCounter = other->mChildTimeCounter; - mChildTimeCounter = mStartChildTimeCounter; + mStartTotalTimeCounter = other->mTotalTimeCounter; + mTotalTimeCounter = mStartTotalTimeCounter; mLastCaller = other->mLastCaller; mActiveCount = other->mActiveCount; @@ -443,8 +438,7 @@ void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) } else { - mStartSelfTimeCounter = mSelfTimeCounter; - mStartChildTimeCounter = mChildTimeCounter; + mStartTotalTimeCounter = mTotalTimeCounter; } } -- cgit v1.2.3 From a6bb68b6e530df91d03abfc062c700ebc4e856aa Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 13 Feb 2013 15:21:20 -0800 Subject: SH-3275 FIX interesting Update viewer metrics system to be more flexible fix for inaccurate optimization of full block time calculations --- indra/llcommon/llfasttimer.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'indra/llcommon/llfasttimer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index f8837a7085..5baf049c03 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -256,12 +256,12 @@ void TimeBlock::processTimes() while(cur_timer && cur_timer->mParentTimerData.mActiveTimer != cur_timer) { U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; - accumulator->mTotalTimeCounter += cumulative_time_delta - (accumulator->mTotalTimeCounter - accumulator->mStartTotalTimeCounter); + accumulator->mTotalTimeCounter += cumulative_time_delta - (accumulator->mTotalTimeCounter - cur_timer->mBlockStartTotalTimeCounter); accumulator->mSelfTimeCounter += cumulative_time_delta - stack_record->mChildTime; stack_record->mChildTime = 0; cur_timer->mStartTime = cur_time; - cur_timer->mStartTotalTimeCounter = accumulator->mTotalTimeCounter; + cur_timer->mBlockStartTotalTimeCounter = accumulator->mTotalTimeCounter; stack_record = &cur_timer->mParentTimerData; accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); @@ -376,7 +376,7 @@ void TimeBlock::dumpCurTimes() } out_str << timerp->getName() << " " - << std::setprecision(3) << total_time_ms.as().value() << " ms, " + << std::setprecision(3) << total_time_ms.as().value() << " ms, " << num_calls << " calls"; llinfos << out_str.str() << llendl; -- cgit v1.2.3