diff options
Diffstat (limited to 'indra/llcommon/llfasttimer.cpp')
-rw-r--r-- | indra/llcommon/llfasttimer.cpp | 645 |
1 files changed, 217 insertions, 428 deletions
diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 0abaf73063..e6233a094e 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -32,8 +32,13 @@ #include "llsingleton.h" #include "lltreeiterators.h" #include "llsdserialize.h" +#include "llunit.h" +#include "llsd.h" +#include "lltracerecording.h" +#include "lltracethreadrecorder.h" #include <boost/bind.hpp> +#include <queue> #if LL_WINDOWS @@ -49,37 +54,36 @@ #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<LLSD> LLFastTimer::sLogQueue; +bool TimeBlock::sLog = false; +std::string TimeBlock::sLogName = ""; +bool TimeBlock::sMetricLog = false; #if LL_LINUX || LL_SOLARIS -U64 LLFastTimer::sClockResolution = 1000000000; // Nanosecond resolution +U64 TimeBlock::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution +U64 TimeBlock::sClockResolution = 1000000; // Microsecond resolution #endif +static LLMutex* sLogLock = NULL; +static std::queue<LLSD> sLogQueue; + + // FIXME: move these declarations to the relevant modules // helper functions -typedef LLTreeDFSPostIter<LLFastTimer::NamedTimer, LLFastTimer::NamedTimer::child_const_iter> timer_tree_bottom_up_iterator_t; +typedef LLTreeDFSPostIter<TimeBlock, TimeBlock::child_const_iter> 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(TimeBlock& 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(&TimeBlock::beginChildren), _1), + boost::bind(boost::mem_fn(&TimeBlock::endChildren), _1)); } static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() @@ -87,14 +91,14 @@ static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() return timer_tree_bottom_up_iterator_t(); } -typedef LLTreeDFSIter<LLFastTimer::NamedTimer, LLFastTimer::NamedTimer::child_const_iter> timer_tree_dfs_iterator_t; +typedef LLTreeDFSIter<TimeBlock, TimeBlock::child_const_iter> 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(TimeBlock& 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(&TimeBlock::beginChildren), _1), + boost::bind(boost::mem_fn(&TimeBlock::endChildren), _1)); } static timer_tree_dfs_iterator_t end_timer_tree() @@ -102,92 +106,50 @@ 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<NamedTimerFactory> -{ -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) +// sort child timers by name +struct SortTimerByName +{ + bool operator()(const TimeBlock* i1, const TimeBlock* i2) { - timer_map_t::iterator found_it = mTimers.find(name); - if (found_it != mTimers.end()) - { - return found_it->second; - } - return NULL; + return i1->getName() < i2->getName(); } - - LLFastTimer::NamedTimer* getRootTimer() { return mTimerRoot; } - - typedef std::multimap<std::string, LLFastTimer::NamedTimer*> 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)) +TimeBlock& TimeBlock::getRootTimeBlock() +{ + static TimeBlock root_timer("root", true, NULL); + return root_timer; +} + +void TimeBlock::pushLog(LLSD log) { - mTimer.setCollapsed(!open); + LLMutexLock lock(sLogLock); + + sLogQueue.push(log); } -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) +void TimeBlock::setLogLock(LLMutex* lock) { + sLogLock = lock; } + //static #if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 TimeBlock::countsPerSecond() { - return sClockResolution >> 8; + return sClockResolution; } #else // windows or x86-mac or x86-linux or x86-solaris -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +U64 TimeBlock::countsPerSecond() { #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<LLUnits::Hertz, U64> 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 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; @@ -198,271 +160,202 @@ U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer firstcall = false; } #endif - return sCPUClockFrequency >> 8; + return sCPUClockFrequency.value(); } #endif -LLFastTimer::FrameState::FrameState() -: mActiveCount(0), - mCalls(0), - mSelfTimeCounter(0), - mParent(NULL), - mLastCaller(NULL), - mMoveUpTree(false) -{} - - -LLFastTimer::NamedTimer::NamedTimer(const std::string& name) -: mName(name), - mCollapsed(true), - mParent(NULL), - mTreeTimeCounter(0), - mCountAverage(0), - mCallAverage(0), - mNeedsSorting(false), - mFrameState(NULL) -{ - 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() -{ - 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) +TimeBlock::TimeBlock(const char* name, bool open, TimeBlock* parent) +: TraceType<TimeBlockAccumulator>(name), + mCollapsed(true) { - 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<NamedTimer*>& children = mParent->getChildren(); - std::vector<NamedTimer*>::iterator found_it = std::find(children.begin(), children.end(), this); - if (found_it != children.end()) - { - children.erase(found_it); - } - } - - mParent = parent; - if (parent) - { - getFrameState().mParent = &parent->getFrameState(); - parent->getChildren().push_back(this); - parent->mNeedsSorting = true; - } + setCollapsed(!open); } -S32 LLFastTimer::NamedTimer::getDepth() +TimeBlockTreeNode& TimeBlock::getTreeNode() const { - S32 depth = 0; - NamedTimer* timerp = mParent; - while(timerp) - { - depth++; - if (timerp->getParent() == timerp) break; - timerp = timerp->mParent; - } - return depth; + TimeBlockTreeNode* nodep = LLTrace::get_thread_recorder()->getTimeBlockTreeNode(getIndex()); + llassert(nodep); + return *nodep; } // static -void LLFastTimer::NamedTimer::processTimes() +void TimeBlock::processTimes() { - if (sCurFrameIndex < 0) return; - - buildHierarchy(); - accumulateTimings(); -} - -// sort child timers by name -struct SortTimerByName -{ - bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2) - { - return i1->getName() < i2->getName(); - } -}; - -//static -void LLFastTimer::NamedTimer::buildHierarchy() -{ - if (sCurFrameIndex < 0 ) return; + get_clock_count(); // good place to calculate clock frequency + U64 cur_time = getCPUClockCount64(); + BlockTimerStackRecord* stack_record = ThreadTimerStack::getInstance(); // set up initial tree + for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), end_it = LLInstanceTracker<TimeBlock>::endInstances(); + it != end_it; + ++it) { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + TimeBlock& timer = *it; + 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::getRootTimeBlock()) { - NamedTimer& timer = *it; - if (&timer == NamedTimerFactory::instance().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()) + TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); + + if (accumulator->mLastCaller) { - timer.setParent(timer.getFrameState().mLastCaller->mTimer); - // no need to push up tree on first use, flag can be set spuriously - timer.getFrameState().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'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(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimeBlock()); it != end_timer_tree_bottom_up(); ++it) { - NamedTimer* timerp = *it; - // skip root timer - if (timerp == NamedTimerFactory::instance().getRootTimer()) continue; + TimeBlock* timerp = *it; - if (timerp->getFrameState().mMoveUpTree) + // sort timers by time last called, so call graph makes sense + TimeBlockTreeNode& tree_node = timerp->getTreeNode(); + if (tree_node.mNeedsSorting) { - // 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; - - // don't bubble up any ancestors until descendants are done bubbling up - it.skipAncestors(); + std::sort(tree_node.mChildren.begin(), tree_node.mChildren.end(), SortTimerByName()); } - } - // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree(); - ++it) - { - NamedTimer* timerp = (*it); - if (timerp->mNeedsSorting) + // skip root timer + if (timerp != &TimeBlock::getRootTimeBlock()) { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + TimeBlockAccumulator* accumulator = timerp->getPrimaryAccumulator(); + + 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->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 + // child-most block locations before their parents + it.skipAncestors(); + } } - timerp->mNeedsSorting = false; } -} - -//static -void LLFastTimer::NamedTimer::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; + BlockTimer* cur_timer = stack_record->mActiveTimer; + TimeBlockAccumulator* accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; - while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) + while(cur_timer && cur_timer->mLastTimerData.mActiveTimer != 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->mFrameState->mSelfTimeCounter += self_time_delta; - cur_data->mFrameState->mTotalTimeCounter += cumulative_time_delta; + U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + 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; + stack_record = &cur_timer->mLastTimerData; + stack_record->mChildTime += cumulative_time_delta; + if (stack_record->mTimeBlock) + { + accumulator = stack_record->mTimeBlock->getPrimaryAccumulator(); + } - cur_timer = cur_timer->mLastTimerData.mCurTimer; + cur_timer = cur_timer->mLastTimerData.mActiveTimer; } - // 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()); - it != end_timer_tree_bottom_up(); + + // reset for next frame + for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), + end_it = LLInstanceTracker<TimeBlock>::endInstances(); + it != end_it; ++it) { - NamedTimer* timerp = (*it); - timerp->mTreeTimeCounter = timerp->getFrameState().mSelfTimeCounter; - for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) - { - timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter; - } + TimeBlock& timer = *it; + TimeBlockAccumulator* accumulator = timer.getPrimaryAccumulator(); - S32 cur_frame = sCurFrameIndex; - if (cur_frame >= 0) - { - // update timer history - 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); - } + 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; + // } + //} } -// static -void LLFastTimer::NamedTimer::resetFrame() + +std::vector<TimeBlock*>::iterator TimeBlock::beginChildren() +{ + return getTreeNode().mChildren.begin(); +} + +std::vector<TimeBlock*>::iterator TimeBlock::endChildren() +{ + return getTreeNode().mChildren.end(); +} + +std::vector<TimeBlock*>& TimeBlock::getChildren() +{ + return getTreeNode().mChildren; +} + +//static +void TimeBlock::logStats() { + // get ready for next frame if (sLog) { //output current frame counts to performance log 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() << llendl; + 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())/((F64)LLProcessorInfo().getCPUFrequency()*1000000.0) << LL_ENDL; + LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit<LLUnits::Hertz, F64>(LLProcessorInfo().getCPUFrequency())) << LL_ENDL; } call_count++; - F64 iclock_freq = 1000.0 / countsPerSecond(); // good place to calculate clock frequency - - F64 total_time = 0; + LLUnit<LLUnits::Seconds, F64> total_time(0); LLSD sd; { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), + end_it = LLInstanceTracker<TimeBlock>::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; - + 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 = total_time + info.mSelfTimeCounter * iclock_freq; + total_time += frame_recording.getLastRecordingPeriod().getSum(timer); } } - sd["Total"]["Time"] = (LLSD::Real) total_time; + sd["Total"]["Time"] = (LLSD::Real) total_time.value(); sd["Total"]["Calls"] = (LLSD::Integer) 1; { @@ -471,162 +364,44 @@ void LLFastTimer::NamedTimer::resetFrame() } } - // reset for next frame - for (instance_iter it = beginInstances(); it != endInstances(); ++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(); - } - } } //static -void LLFastTimer::NamedTimer::reset() +void TimeBlock::dumpCurTimes() { - resetFrame(); // reset frame data - - // walk up stack of active timers and reset start times to current time - // effectively zeroing out any accumulated time - U32 cur_time = getCPUClockCount32(); - - // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; - LLFastTimer* 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 (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - NamedTimer& timer = *it; - if (&timer != NamedTimerFactory::instance().getRootTimer()) - { - timer.setParent(NamedTimerFactory::instance().getRootTimer()); - } - - timer.mCountAverage = 0; - timer.mCallAverage = 0; - memset(timer.mCountHistory, 0, sizeof(U32) * HISTORY_NUM); - memset(timer.mCallHistory, 0, sizeof(U32) * HISTORY_NUM); - } - } - - sLastFrameIndex = 0; - sCurFrameIndex = 0; -} - -U32 LLFastTimer::NamedTimer::getHistoricalCount(S32 history_index) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; - return mCountHistory[history_idx]; -} - -U32 LLFastTimer::NamedTimer::getHistoricalCalls(S32 history_index ) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; - return mCallHistory[history_idx]; -} - -LLFastTimer::FrameState& LLFastTimer::NamedTimer::getFrameState() const -{ - return *mFrameState; -} - -std::vector<LLFastTimer::NamedTimer*>::const_iterator LLFastTimer::NamedTimer::beginChildren() -{ - return mChildren.begin(); -} - -std::vector<LLFastTimer::NamedTimer*>::const_iterator LLFastTimer::NamedTimer::endChildren() -{ - return mChildren.end(); -} - -std::vector<LLFastTimer::NamedTimer*>& LLFastTimer::NamedTimer::getChildren() -{ - return mChildren; -} - -//static -void LLFastTimer::nextFrame() -{ - countsPerSecond(); // good place to calculate clock frequency - U64 frame_time = getCPUClockCount64(); - if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) - { - llinfos << "Slow frame, fast timers inaccurate" << llendl; - } - - if (!sPauseHistory) - { - NamedTimer::processTimes(); - sLastFrameIndex = sCurFrameIndex++; - } - - // get ready for next frame - NamedTimer::resetFrame(); - sLastFrameTime = frame_time; -} - -//static -void LLFastTimer::dumpCurTimes() -{ - // accumulate timings, etc. - NamedTimer::processTimes(); - - F64 clock_freq = (F64)countsPerSecond(); - F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds + 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(*NamedTimerFactory::instance().getRootTimer()); + for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimeBlock()); it != end_timer_tree(); ++it) { - NamedTimer* timerp = (*it); - F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); + TimeBlock* timerp = (*it); + LLUnit<LLUnits::Seconds, F64> 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() << " " - << std::setprecision(3) << total_time_ms << " ms, " - << timerp->getHistoricalCalls(0) << " calls"; + << std::setprecision(3) << total_time_ms.as<LLUnits::Milliseconds, F32>().value() << " ms, " + << num_calls << " calls"; llinfos << out_str.str() << llendl; } } -//static -void LLFastTimer::reset() -{ - NamedTimer::reset(); -} - - //static -void LLFastTimer::writeLog(std::ostream& os) +void TimeBlock::writeLog(std::ostream& os) { while (!sLogQueue.empty()) { @@ -637,22 +412,36 @@ void LLFastTimer::writeLog(std::ostream& os) } } -//static -const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& name) +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// +// TimeBlockAccumulator +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// + +TimeBlockAccumulator::TimeBlockAccumulator() +: mSelfTimeCounter(0), + mTotalTimeCounter(0), + mCalls(0), + mLastCaller(NULL), + mActiveCount(0), + mMoveUpTree(false), + mParent(NULL) +{} + +void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other ) { - return NamedTimerFactory::instance().getTimerByName(name); + mSelfTimeCounter += other.mSelfTimeCounter; + mTotalTimeCounter += other.mTotalTimeCounter; + mCalls += other.mCalls; + mLastCaller = other.mLastCaller; + mActiveCount = other.mActiveCount; + mMoveUpTree = other.mMoveUpTree; + mParent = other.mParent; } -//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; -//} - +void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) +{ + mTotalTimeCounter = 0; + mSelfTimeCounter = 0; + mCalls = 0; +} +} // namespace LLTrace |