diff options
| author | Richard Linden <none@none> | 2014-03-12 12:48:43 -0700 | 
|---|---|---|
| committer | Richard Linden <none@none> | 2014-03-12 12:48:43 -0700 | 
| commit | 5b846ed2a6dce6c5801aa74d0f36a1c7525fbcba (patch) | |
| tree | 438dd649dbcc0584709251c6926a476b0db02f85 /indra/llcommon/llfasttimer.cpp | |
| parent | cb91708332b8b8ddfe27808602ec5f43f11c24c2 (diff) | |
| parent | 5f513242890068f569df7e50a5ac0ba3bdd23f05 (diff) | |
merge with release
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  | 
