diff options
Diffstat (limited to 'indra/llcommon/llfasttimer.cpp')
-rwxr-xr-x | indra/llcommon/llfasttimer.cpp | 662 |
1 files changed, 247 insertions, 415 deletions
diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index 58db7d0d17..3d28cd15b0 100755 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -32,8 +32,13 @@ #include "llsingleton.h" #include "lltreeiterators.h" #include "llsdserialize.h" +#include "llunits.h" +#include "llsd.h" +#include "lltracerecording.h" +#include "lltracethreadrecorder.h" #include <boost/bind.hpp> +#include <queue> #if LL_WINDOWS @@ -49,140 +54,115 @@ #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 BlockTimer::sLog = false; +std::string BlockTimer::sLogName = ""; +bool BlockTimer::sMetricLog = false; #if LL_LINUX || LL_SOLARIS -U64 LLFastTimer::sClockResolution = 1000000000; // Nanosecond resolution +U64 BlockTimer::sClockResolution = 1000000000; // Nanosecond resolution #else -U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution +U64 BlockTimer::sClockResolution = 1000000; // Microsecond resolution #endif -// 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; +static LLMutex* sLogLock = NULL; +static std::queue<LLSD> sLogQueue; -static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::NamedTimer& id) +block_timer_tree_df_iterator_t begin_block_timer_tree_df(BlockTimerStatHandle& 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)); + return block_timer_tree_df_iterator_t(&id, + boost::bind(boost::mem_fn(&BlockTimerStatHandle::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimerStatHandle::endChildren), _1)); } -static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() +block_timer_tree_df_iterator_t end_block_timer_tree_df() { - return timer_tree_bottom_up_iterator_t(); + return block_timer_tree_df_iterator_t(); } -typedef LLTreeDFSIter<LLFastTimer::NamedTimer, LLFastTimer::NamedTimer::child_const_iter> timer_tree_dfs_iterator_t; - +block_timer_tree_df_post_iterator_t begin_block_timer_tree_df_post(BlockTimerStatHandle& id) +{ + return block_timer_tree_df_post_iterator_t(&id, + boost::bind(boost::mem_fn(&BlockTimerStatHandle::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimerStatHandle::endChildren), _1)); +} -static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::NamedTimer& id) +block_timer_tree_df_post_iterator_t end_block_timer_tree_df_post() { - 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)); + return block_timer_tree_df_post_iterator_t(); } -static timer_tree_dfs_iterator_t end_timer_tree() +block_timer_tree_bf_iterator_t begin_block_timer_tree_bf(BlockTimerStatHandle& id) { - return timer_tree_dfs_iterator_t(); + return block_timer_tree_bf_iterator_t(&id, + boost::bind(boost::mem_fn(&BlockTimerStatHandle::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimerStatHandle::endChildren), _1)); } -// factory class that creates NamedTimers via static DeclareTimer objects -class NamedTimerFactory : public LLSingleton<NamedTimerFactory> -{ -public: - NamedTimerFactory() - : mTimerRoot(new LLFastTimer::NamedTimer("root")) +block_timer_tree_bf_iterator_t end_block_timer_tree_bf() { - mRootFrameState.setNamedTimer(mTimerRoot); - mTimerRoot->setFrameState(&mRootFrameState); - mTimerRoot->mParent = mTimerRoot; - mTimerRoot->setCollapsed(false); - mRootFrameState.mParent = &mRootFrameState; + return block_timer_tree_bf_iterator_t(); } - ~NamedTimerFactory() +block_timer_tree_df_iterator_t begin_timer_tree(BlockTimerStatHandle& id) { - std::for_each(mTimers.begin(), mTimers.end(), DeletePairedPointer()); - mTimers.clear(); - - delete mTimerRoot; + return block_timer_tree_df_iterator_t(&id, + boost::bind(boost::mem_fn(&BlockTimerStatHandle::beginChildren), _1), + boost::bind(boost::mem_fn(&BlockTimerStatHandle::endChildren), _1)); } - LLFastTimer::NamedTimer& createNamedTimer(const std::string& name, LLFastTimer::FrameState* state) +block_timer_tree_df_iterator_t end_timer_tree() { - LLFastTimer::NamedTimer* timer = new LLFastTimer::NamedTimer(name); - timer->setFrameState(state); - timer->setParent(mTimerRoot); - mTimers.insert(std::make_pair(name, timer)); + return block_timer_tree_df_iterator_t(); +} - return *timer; - } - LLFastTimer::NamedTimer* getTimerByName(const std::string& name) +// sort child timers by name +struct SortTimerByName { - timer_map_t::iterator found_it = mTimers.find(name); - if (found_it != mTimers.end()) + bool operator()(const BlockTimerStatHandle* i1, const BlockTimerStatHandle* i2) { - return found_it->second; + return i1->getName() < i2->getName(); } - return NULL; - } - - 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)) +static BlockTimerStatHandle sRootTimer("root", NULL); +BlockTimerStatHandle& BlockTimer::getRootTimeBlock() { - mTimer.setCollapsed(!open); + return sRootTimer; + } + +void BlockTimer::pushLog(LLSD log) +{ + LLMutexLock lock(sLogLock); + + sLogQueue.push(log); } -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) +void BlockTimer::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 BlockTimer::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 BlockTimer::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); - - // we drop the low-order byte in our timers, so report a lower frequency + static LLUnit<U64, LLUnits::Hertz> sCPUClockFrequency = LLProcessorInfo().getCPUFrequency(); + return sCPUClockFrequency.value(); #else // If we're not using RDTSC, each fasttimer tick is just a performance counter tick. // Not redefining the clock frequency itself (in llprocessor.cpp/calculate_cpu_frequency()) @@ -194,270 +174,211 @@ U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer QueryPerformanceFrequency((LARGE_INTEGER*)&sCPUClockFrequency); firstcall = false; } + return sCPUClockFrequency.value(); #endif - return sCPUClockFrequency >> 8; } #endif -LLFastTimer::FrameState::FrameState() -: mActiveCount(0), - mCalls(0), - mSelfTimeCounter(0), - mParent(NULL), - mLastCaller(NULL), - mMoveUpTree(false) +BlockTimerStatHandle::BlockTimerStatHandle(const char* name, const char* description) +: StatType<TimeBlockAccumulator>(name, description) {} - -LLFastTimer::NamedTimer::NamedTimer(const std::string& name) -: mName(name), - mCollapsed(true), - mParent(NULL), - mTotalTimeCounter(0), - mCountAverage(0), - mCallAverage(0), - mNeedsSorting(false), - mFrameState(NULL) +TimeBlockTreeNode& BlockTimerStatHandle::getTreeNode() const { - mCountHistory = new U32[HISTORY_NUM]; - memset(mCountHistory, 0, sizeof(U32) * HISTORY_NUM); - mCallHistory = new U32[HISTORY_NUM]; - memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); + TimeBlockTreeNode* nodep = LLTrace::get_thread_recorder()->getTimeBlockTreeNode(getIndex()); + llassert(nodep); + return *nodep; } -LLFastTimer::NamedTimer::~NamedTimer() -{ - delete[] mCountHistory; - delete[] mCallHistory; -} -std::string LLFastTimer::NamedTimer::getToolTip(S32 history_idx) +void BlockTimer::bootstrapTimerTree() { - 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 + for (BlockTimerStatHandle::instance_tracker_t::instance_iter it = BlockTimerStatHandle::instance_tracker_t::beginInstances(), end_it = BlockTimerStatHandle::instance_tracker_t::endInstances(); + it != end_it; + ++it) { - return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getHistoricalCount(history_idx) * ms_multiplier), (S32)getHistoricalCalls(history_idx)); - } -} + BlockTimerStatHandle& timer = static_cast<BlockTimerStatHandle&>(*it); + if (&timer == &BlockTimer::getRootTimeBlock()) continue; -void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) + // bootstrap tree construction by attaching to last timer to be on stack + // when this timer was called + if (timer.getParent() == &BlockTimer::getRootTimeBlock()) { - llassert_always(parent != this); - llassert_always(parent != NULL); + TimeBlockAccumulator& accumulator = timer.getCurrentAccumulator(); - if (mParent) + if (accumulator.mLastCaller) { - // 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); + 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; } - - mParent = parent; - if (parent) - { - getFrameState().mParent = &parent->getFrameState(); - parent->getChildren().push_back(this); - parent->mNeedsSorting = true; } } -S32 LLFastTimer::NamedTimer::getDepth() +// 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 +void BlockTimer::incrementalUpdateTimerTree() { - S32 depth = 0; - NamedTimer* timerp = mParent; - while(timerp) + for(block_timer_tree_df_post_iterator_t it = begin_block_timer_tree_df_post(BlockTimer::getRootTimeBlock()); + it != end_block_timer_tree_df_post(); + ++it) { - depth++; - if (timerp->getParent() == timerp) break; - timerp = timerp->mParent; - } - return depth; -} + BlockTimerStatHandle* timerp = *it; -// static -void LLFastTimer::NamedTimer::processTimes() + // sort timers by time last called, so call graph makes sense + TimeBlockTreeNode& tree_node = timerp->getTreeNode(); + if (tree_node.mNeedsSorting) { - if (sCurFrameIndex < 0) return; - - buildHierarchy(); - accumulateTimings(); + std::sort(tree_node.mChildren.begin(), tree_node.mChildren.end(), SortTimerByName()); } -// sort child timers by name -struct SortTimerByName + // skip root timer + if (timerp != &BlockTimer::getRootTimeBlock()) { - bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2) - { - return i1->getName() < i2->getName(); - } -}; + TimeBlockAccumulator& accumulator = timerp->getCurrentAccumulator(); -//static -void LLFastTimer::NamedTimer::buildHierarchy() + if (accumulator.mMoveUpTree) { - if (sCurFrameIndex < 0 ) return; - - // set up initial tree - { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - 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()) - { - timer.setParent(timer.getFrameState().mLastCaller->mTimer); - // no need to push up tree on first use, flag can be set spuriously - timer.getFrameState().mMoveUpTree = false; - } - } - } - - // 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()); - it != end_timer_tree_bottom_up(); - ++it) - { - NamedTimer* timerp = *it; - // skip root timer - if (timerp == NamedTimerFactory::instance().getRootTimer()) continue; - - if (timerp->getFrameState().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->getFrameState().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 + // 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(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree(); - ++it) + +void BlockTimer::updateTimes() { - NamedTimer* timerp = (*it); - if (timerp->mNeedsSorting) + // walk up stack of active timers and accumulate current time while leaving timing structures active + BlockTimerStackRecord* stack_record = LLThreadLocalSingletonPointer<BlockTimerStackRecord>::getInstance(); + if (!stack_record) return; + + U64 cur_time = getCPUClockCount64(); + BlockTimer* cur_timer = stack_record->mActiveTimer; + TimeBlockAccumulator* accumulator = &stack_record->mTimeBlock->getCurrentAccumulator(); + + while(cur_timer + && cur_timer->mParentTimerData.mActiveTimer != cur_timer) // root defined by parent pointing to self { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); - } - timerp->mNeedsSorting = false; + U64 cumulative_time_delta = cur_time - cur_timer->mStartTime; + cur_timer->mStartTime = cur_time; + + accumulator->mTotalTimeCounter += cumulative_time_delta; + accumulator->mSelfTimeCounter += cumulative_time_delta - stack_record->mChildTime; + stack_record->mChildTime = 0; + + stack_record = &cur_timer->mParentTimerData; + accumulator = &stack_record->mTimeBlock->getCurrentAccumulator(); + cur_timer = stack_record->mActiveTimer; + + stack_record->mChildTime += cumulative_time_delta; } } +static LLTrace::BlockTimerStatHandle FTM_PROCESS_TIMES("Process FastTimer Times"); + +// not thread safe, so only call on main thread //static -void LLFastTimer::NamedTimer::accumulateTimings() +void BlockTimer::processTimes() { - U32 cur_time = getCPUClockCount32(); +#if LL_TRACE_ENABLED + LL_RECORD_BLOCK_TIME(FTM_PROCESS_TIMES); + get_clock_count(); // good place to calculate clock frequency - // walk up stack of active timers and accumulate current time while leaving timing structures active - LLFastTimer* cur_timer = sCurTimerData.mCurTimer; - // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; - 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_timer->mFrameState->mSelfTimeCounter += self_time_delta; - cur_timer->mStartTime = cur_time; + // set up initial tree + bootstrapTimerTree(); - cur_data = &cur_timer->mLastTimerData; - cur_data->mChildTime += cumulative_time_delta; + incrementalUpdateTimerTree(); - cur_timer = cur_timer->mLastTimerData.mCurTimer; - } + updateTimes(); - // 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 (BlockTimerStatHandle::instance_tracker_t::instance_iter it = BlockTimerStatHandle::instance_tracker_t::beginInstances(), + end_it = BlockTimerStatHandle::instance_tracker_t::endInstances(); + it != end_it; ++it) { - NamedTimer* timerp = (*it); - timerp->mTotalTimeCounter = timerp->getFrameState().mSelfTimeCounter; - for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) + BlockTimerStatHandle& timer = static_cast<BlockTimerStatHandle&>(*it); + TimeBlockAccumulator& accumulator = timer.getCurrentAccumulator(); + + accumulator.mLastCaller = NULL; + accumulator.mMoveUpTree = false; + } +#endif +} + +std::vector<BlockTimerStatHandle*>::iterator BlockTimerStatHandle::beginChildren() { - timerp->mTotalTimeCounter += (*child_it)->mTotalTimeCounter; + return getTreeNode().mChildren.begin(); } - S32 cur_frame = sCurFrameIndex; - if (cur_frame >= 0) +std::vector<BlockTimerStatHandle*>::iterator BlockTimerStatHandle::endChildren() { - // update timer history - int hidx = cur_frame % HISTORY_NUM; + return getTreeNode().mChildren.end(); +} - timerp->mCountHistory[hidx] = timerp->mTotalTimeCounter; - timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTotalTimeCounter) / (cur_frame+1); - timerp->mCallHistory[hidx] = timerp->getFrameState().mCalls; - timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->getFrameState().mCalls) / (cur_frame+1); - } +std::vector<BlockTimerStatHandle*>& BlockTimerStatHandle::getChildren() +{ + return getTreeNode().mChildren; } + +bool BlockTimerStatHandle::hasChildren() +{ + return ! getTreeNode().mChildren.empty(); } // static -void LLFastTimer::NamedTimer::resetFrame() +void BlockTimer::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() / (F64HertzImplicit)LLProcessorInfo().getCPUFrequency()) << LL_ENDL; } call_count++; - F64 iclock_freq = 1000.0 / countsPerSecond(); // good place to calculate clock frequency - - F64 total_time = 0; + F64Seconds total_time(0); LLSD sd; { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) + for (BlockTimerStatHandle::instance_tracker_t::instance_iter it = BlockTimerStatHandle::instance_tracker_t::beginInstances(), + end_it = BlockTimerStatHandle::instance_tracker_t::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; + BlockTimerStatHandle& timer = static_cast<BlockTimerStatHandle&>(*it); + LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording(); + sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecording().getSum(timer).value()); + sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecording().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.getLastRecording().getSum(timer); } } - sd["Total"]["Time"] = (LLSD::Real) total_time; + sd["Total"]["Time"] = (LLSD::Real) total_time.value(); sd["Total"]["Calls"] = (LLSD::Integer) 1; { @@ -466,168 +387,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() -{ - 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 -LLFastTimer::NamedTimer& LLFastTimer::NamedTimer::getRootNamedTimer() -{ - return *NamedTimerFactory::instance().getRootTimer(); -} - -//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() +void BlockTimer::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.getLastRecording(); // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); + for(block_timer_tree_df_iterator_t it = begin_timer_tree(BlockTimer::getRootTimeBlock()); it != end_timer_tree(); ++it) { - NamedTimer* timerp = (*it); - F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); + BlockTimerStatHandle* timerp = (*it); + F64Seconds total_time = 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; + if (total_time < F32Milliseconds(0.1f)) continue; std::ostringstream out_str; - for (S32 i = 0; i < timerp->getDepth(); i++) + BlockTimerStatHandle* 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.valueInUnits<LLUnits::Milliseconds>() << " ms, " + << num_calls << " calls"; - llinfos << out_str.str() << llendl; - } + LL_INFOS() << out_str.str() << LL_ENDL; } - -//static -void LLFastTimer::reset() -{ - NamedTimer::reset(); } - //static -void LLFastTimer::writeLog(std::ostream& os) +void BlockTimer::writeLog(std::ostream& os) { while (!sLogQueue.empty()) { @@ -638,22 +435,57 @@ void LLFastTimer::writeLog(std::ostream& os) } } -//static -const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& name) +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// +// TimeBlockAccumulator +////////////////////////////////////////////////////////////////////////////////////////////////////////////////// + +TimeBlockAccumulator::TimeBlockAccumulator() +: mTotalTimeCounter(0), + mSelfTimeCounter(0), + mCalls(0), + mLastCaller(NULL), + mActiveCount(0), + mMoveUpTree(false), + mParent(NULL) +{} + +void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other, EBufferAppendType append_type ) { - return NamedTimerFactory::instance().getTimerByName(name); +#if LL_TRACE_ENABLED + // we can't merge two unrelated time block samples, as that will screw with the nested timings + // due to the call hierarchy of each thread + llassert(append_type == SEQUENTIAL); + mTotalTimeCounter += other.mTotalTimeCounter; + mSelfTimeCounter += other.mSelfTimeCounter; + mCalls += other.mCalls; + mLastCaller = other.mLastCaller; + mActiveCount = other.mActiveCount; + mMoveUpTree = other.mMoveUpTree; + mParent = other.mParent; +#endif } -LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) -: mFrameState(state) +void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other ) +{ + mCalls = 0; + mSelfTimeCounter = 0; + mTotalTimeCounter = 0; + + if (other) { - U32 start_time = getCPUClockCount32(); - mStartTime = start_time; - mFrameState->mActiveCount++; - LLFastTimer::sCurTimerData.mCurTimer = this; - LLFastTimer::sCurTimerData.mFrameState = mFrameState; - LLFastTimer::sCurTimerData.mChildTime = 0; - mLastTimerData = LLFastTimer::sCurTimerData; + mLastCaller = other->mLastCaller; + mActiveCount = other->mActiveCount; + mMoveUpTree = other->mMoveUpTree; + mParent = other->mParent; + } +} + +F64Seconds BlockTimer::getElapsedTime() +{ + U64 total_time = getCPUClockCount64() - mStartTime; + + return F64Seconds((F64)total_time / (F64)BlockTimer::countsPerSecond()); } +} // namespace LLTrace |