summaryrefslogtreecommitdiff
path: root/indra/llcommon/llfasttimer.cpp
diff options
context:
space:
mode:
authorRichard Linden <none@none>2013-11-06 17:22:04 -0800
committerRichard Linden <none@none>2013-11-06 17:22:04 -0800
commitfe518bde8e6db65d3d6b178c200410b1346639a4 (patch)
treed738e12f8391a675d36aae9d59ced8104846008c /indra/llcommon/llfasttimer.cpp
parentea1e1b0925b386cf83178539b8eae9e25c573548 (diff)
parentd9d46d908c0573dbcd45ec2a1bea56966823343b (diff)
merge with release
Diffstat (limited to 'indra/llcommon/llfasttimer.cpp')
-rwxr-xr-xindra/llcommon/llfasttimer.cpp693
1 files changed, 261 insertions, 432 deletions
diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp
index 01b6e60d2b..9b093e8936 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,139 +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
+static LLMutex* sLogLock = NULL;
+static std::queue<LLSD> sLogQueue;
-// helper functions
-typedef LLTreeDFSPostIter<LLFastTimer::NamedTimer, LLFastTimer::NamedTimer::child_const_iter> timer_tree_bottom_up_iterator_t;
-
-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;
-
-
-static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::NamedTimer& id)
+block_timer_tree_df_post_iterator_t begin_block_timer_tree_df_post(BlockTimerStatHandle& 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));
+ 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 end_timer_tree()
+block_timer_tree_df_post_iterator_t end_block_timer_tree_df_post()
{
- return timer_tree_dfs_iterator_t();
+ return block_timer_tree_df_post_iterator_t();
}
-// factory class that creates NamedTimers via static DeclareTimer objects
-class NamedTimerFactory : public LLSingleton<NamedTimerFactory>
+block_timer_tree_bf_iterator_t begin_block_timer_tree_bf(BlockTimerStatHandle& id)
{
-public:
- NamedTimerFactory()
- : mTimerRoot(new LLFastTimer::NamedTimer("root"))
- {
- mRootFrameState.setNamedTimer(mTimerRoot);
- mTimerRoot->setFrameState(&mRootFrameState);
- mTimerRoot->mParent = mTimerRoot;
- mTimerRoot->setCollapsed(false);
- mRootFrameState.mParent = &mRootFrameState;
- }
+ return block_timer_tree_bf_iterator_t(&id,
+ boost::bind(boost::mem_fn(&BlockTimerStatHandle::beginChildren), _1),
+ boost::bind(boost::mem_fn(&BlockTimerStatHandle::endChildren), _1));
+}
- ~NamedTimerFactory()
- {
- std::for_each(mTimers.begin(), mTimers.end(), DeletePairedPointer());
+block_timer_tree_bf_iterator_t end_block_timer_tree_bf()
+{
+ return block_timer_tree_bf_iterator_t();
+}
- delete mTimerRoot;
- }
+block_timer_tree_df_iterator_t begin_timer_tree(BlockTimerStatHandle& id)
+{
+ 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)
- {
- LLFastTimer::NamedTimer* timer = new LLFastTimer::NamedTimer(name);
- timer->setFrameState(state);
- timer->setParent(mTimerRoot);
- mTimers.insert(std::make_pair(name, timer));
+block_timer_tree_df_iterator_t end_timer_tree()
+{
+ return block_timer_tree_df_iterator_t();
+}
- return *timer;
- }
- LLFastTimer::NamedTimer* getTimerByName(const std::string& name)
+// sort child timers by name
+struct SortTimerByName
+{
+ bool operator()(const BlockTimerStatHandle* i1, const BlockTimerStatHandle* i2)
{
- 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<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;
+ return i1->getName() < i2->getName();
+ }
};
-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;
}
-LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name)
-: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState))
+void BlockTimer::pushLog(LLSD log)
{
+ LLMutexLock lock(sLogLock);
+
+ sLogQueue.push(log);
}
+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())
@@ -193,440 +174,255 @@ 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;
+
+ // bootstrap tree construction by attaching to last timer to be on stack
+ // when this timer was called
+ if (timer.getParent() == &BlockTimer::getRootTimeBlock())
+ {
+ TimeBlockAccumulator& accumulator = timer.getCurrentAccumulator();
+
+ if (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;
+ }
}
}
-void LLFastTimer::NamedTimer::setParent(NamedTimer* parent)
+// 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()
{
- llassert_always(parent != this);
- llassert_always(parent != NULL);
-
- if (mParent)
+ 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)
{
- // subtract our accumulated from previous parent
- for (S32 i = 0; i < HISTORY_NUM; i++)
+ BlockTimerStatHandle* timerp = *it;
+
+ // sort timers by time last called, so call graph makes sense
+ TimeBlockTreeNode& tree_node = timerp->getTreeNode();
+ if (tree_node.mNeedsSorting)
{
- mParent->mCountHistory[i] -= mCountHistory[i];
+ std::sort(tree_node.mChildren.begin(), tree_node.mChildren.end(), SortTimerByName());
}
- // 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())
+ // skip root timer
+ if (timerp != &BlockTimer::getRootTimeBlock())
{
- children.erase(found_it);
- }
- }
+ TimeBlockAccumulator& accumulator = timerp->getCurrentAccumulator();
- mParent = parent;
- if (parent)
- {
- getFrameState().mParent = &parent->getFrameState();
- parent->getChildren().push_back(this);
- parent->mNeedsSorting = true;
+ 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();
+ }
+ }
}
}
-S32 LLFastTimer::NamedTimer::getDepth()
-{
- S32 depth = 0;
- NamedTimer* timerp = mParent;
- while(timerp)
- {
- depth++;
- if (timerp->getParent() == timerp) break;
- timerp = timerp->mParent;
- }
- return depth;
-}
-// static
-void LLFastTimer::NamedTimer::processTimes()
+void BlockTimer::updateTimes()
{
- if (sCurFrameIndex < 0) return;
+ // 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;
- buildHierarchy();
- accumulateTimings();
-}
+ U64 cur_time = getCPUClockCount64();
+ BlockTimer* cur_timer = stack_record->mActiveTimer;
+ TimeBlockAccumulator* accumulator = &stack_record->mTimeBlock->getCurrentAccumulator();
-// sort child timers by name
-struct SortTimerByName
-{
- bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2)
+ while(cur_timer
+ && cur_timer->mParentTimerData.mActiveTimer != cur_timer) // root defined by parent pointing to self
{
- return i1->getName() < i2->getName();
+ 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::buildHierarchy()
+void BlockTimer::processTimes()
{
- if (sCurFrameIndex < 0 ) return;
+ LL_RECORD_BLOCK_TIME(FTM_PROCESS_TIMES);
+ get_clock_count(); // good place to calculate clock frequency
// 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;
- }
- }
- }
+ bootstrapTimerTree();
- // 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;
+ incrementalUpdateTimerTree();
- if (timerp->getFrameState().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;
-
- // don't bubble up any ancestors until descendants are done bubbling up
- it.skipAncestors();
- }
- }
+ updateTimes();
- // 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();
+ // 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);
- if (timerp->mNeedsSorting)
- {
- std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName());
- }
- timerp->mNeedsSorting = false;
+ BlockTimerStatHandle& timer = static_cast<BlockTimerStatHandle&>(*it);
+ TimeBlockAccumulator& accumulator = timer.getCurrentAccumulator();
+
+ accumulator.mLastCaller = NULL;
+ accumulator.mMoveUpTree = false;
}
}
-//static
-void LLFastTimer::NamedTimer::accumulateTimings()
+std::vector<BlockTimerStatHandle*>::iterator BlockTimerStatHandle::beginChildren()
{
- U32 cur_time = getCPUClockCount32();
-
- // 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;
-
- cur_data = &cur_timer->mLastTimerData;
- cur_data->mChildTime += cumulative_time_delta;
-
- cur_timer = cur_timer->mLastTimerData.mCurTimer;
- }
+ return getTreeNode().mChildren.begin();
+}
- // 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();
- ++it)
- {
- NamedTimer* timerp = (*it);
- timerp->mTotalTimeCounter = timerp->getFrameState().mSelfTimeCounter;
- for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it)
- {
- timerp->mTotalTimeCounter += (*child_it)->mTotalTimeCounter;
- }
+std::vector<BlockTimerStatHandle*>::iterator BlockTimerStatHandle::endChildren()
+{
+ return getTreeNode().mChildren.end();
+}
- S32 cur_frame = sCurFrameIndex;
- if (cur_frame >= 0)
- {
- // update timer history
- int hidx = cur_frame % HISTORY_NUM;
+std::vector<BlockTimerStatHandle*>& BlockTimerStatHandle::getChildren()
+{
+ return getTreeNode().mChildren;
+}
- 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);
- }
- }
+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;
{
LLMutexLock lock(sLogLock);
sLogQueue.push(sd);
}
- }
-
- // 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()
+void BlockTimer::dumpCurTimes()
{
- 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.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())
{
@@ -637,22 +433,55 @@ 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 )
+{
+ // 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;
+}
+
+void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other )
{
- return NamedTimerFactory::instance().getTimerByName(name);
+ mCalls = 0;
+ mSelfTimeCounter = 0;
+ mTotalTimeCounter = 0;
+
+ if (other)
+ {
+ mLastCaller = other->mLastCaller;
+ mActiveCount = other->mActiveCount;
+ mMoveUpTree = other->mMoveUpTree;
+ mParent = other->mParent;
+ }
}
-LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state)
-: mFrameState(state)
+F64Seconds BlockTimer::getElapsedTime()
{
- U32 start_time = getCPUClockCount32();
- mStartTime = start_time;
- mFrameState->mActiveCount++;
- LLFastTimer::sCurTimerData.mCurTimer = this;
- LLFastTimer::sCurTimerData.mFrameState = mFrameState;
- LLFastTimer::sCurTimerData.mChildTime = 0;
- mLastTimerData = LLFastTimer::sCurTimerData;
+ U64 total_time = getCPUClockCount64() - mStartTime;
+
+ return F64Seconds((F64)total_time / (F64)BlockTimer::countsPerSecond());
}
+} // namespace LLTrace