SH-3406 WIP convert fast timers to lltrace system

removed some potential data races
got memory stats recording in trace system

1 files changed, 139 insertions, 187 deletions

diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp
index 37e0fbac0a..f4fa8f1e61 100644
--- a/indra/llcommon/llfasttimer.cpp
+++ b/indra/llcommon/llfasttimer.cpp
@@ -59,11 +59,6 @@ namespace LLTrace
 //////////////////////////////////////////////////////////////////////////////
 // statics
 
-S32         TimeBlock::sCurFrameIndex   = -1;
-S32         TimeBlock::sLastFrameIndex  = -1;
-U64         TimeBlock::sLastFrameTime   = TimeBlock::getCPUClockCount64();
-bool        TimeBlock::sPauseHistory    = 0;
-bool        TimeBlock::sResetHistory    = 0;
 bool        TimeBlock::sLog		     = false;
 std::string TimeBlock::sLogName         = "";
 bool        TimeBlock::sMetricLog       = false;
@@ -220,143 +215,126 @@ void TimeBlock::setParent(TimeBlock* parent)
 	}
 }
 
-S32 TimeBlock::getDepth()
-{
-	S32 depth = 0;
-	TimeBlock* timerp = mParent;
-	while(timerp)
-	{
-		depth++;
-		if (timerp->getParent() == timerp) break;
-		timerp = timerp->mParent;
-	}
-	return depth;
-}
-
 // static
 void TimeBlock::processTimes()
 {
-	//void TimeBlock::buildHierarchy()
+	get_clock_count(); // good place to calculate clock frequency
+	U64 cur_time = getCPUClockCount64();
+	CurTimerData* cur_data = sCurTimerData.get();
+
+	// set up initial tree
+	for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), end_it = LLInstanceTracker<TimeBlock>::endInstances(); 
+		it != end_it; 
+		++it)
 	{
-		// set up initial tree
+		TimeBlock& timer = *it;
+		if (&timer == &TimeBlock::getRootTimer()) continue;
+
+		// bootstrap tree construction by attaching to last timer to be on stack
+		// when this timer was called
+		if (timer.mParent == &TimeBlock::getRootTimer())
 		{
-			for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), end_it = LLInstanceTracker<TimeBlock>::endInstances(); it != end_it; ++it)
+			TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator();
+
+			if (accumulator.mLastCaller)
 			{
-				TimeBlock& timer = *it;
-				if (&timer == &TimeBlock::getRootTimer()) continue;
-
-				// bootstrap tree construction by attaching to last timer to be on stack
-				// when this timer was called
-				if (timer.mParent == &TimeBlock::getRootTimer())
-				{
-					TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()];
-
-					if (tree_node.mLastCaller)
-					{
-						timer.setParent(tree_node.mLastCaller);
-					}
-					// no need to push up tree on first use, flag can be set spuriously
-					tree_node.mMoveUpTree = false;
-				}
+				timer.setParent(accumulator.mLastCaller);
+				accumulator.mParent = accumulator.mLastCaller;
 			}
+			// no need to push up tree on first use, flag can be set spuriously
+			accumulator.mMoveUpTree = false;
 		}
+	}
 
-		// bump timers up tree if they have been flagged as being in the wrong place
-		// do this in a bottom up order to promote descendants first before promoting ancestors
-		// this preserves partial order derived from current frame's observations
-		for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer());
-			it != end_timer_tree_bottom_up();
-			++it)
+	// bump timers up tree if they have been flagged as being in the wrong place
+	// do this in a bottom up order to promote descendants first before promoting ancestors
+	// this preserves partial order derived from current frame's observations
+	for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer());
+		it != end_timer_tree_bottom_up();
+		++it)
+	{
+		TimeBlock* timerp = *it;
+
+		// sort timers by time last called, so call graph makes sense
+		if (timerp->mNeedsSorting)
 		{
-			TimeBlock* timerp = *it;
-			// skip root timer
-			if (timerp == &TimeBlock::getRootTimer()) continue;
-			TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timerp->getIndex()];
+			std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName());
+		}
+
+		// skip root timer
+		if (timerp != &TimeBlock::getRootTimer())
+		{
+			TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator();
 
-			if (tree_node.mMoveUpTree)
+			if (accumulator.mMoveUpTree)
 			{
 				// since ancestors have already been visited, re-parenting won't affect tree traversal
 				//step up tree, bringing our descendants with us
 				LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() <<
 					" to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL;
 				timerp->setParent(timerp->getParent()->getParent());
-				tree_node.mMoveUpTree = false;
+				accumulator.mParent = timerp->mParent;
+				accumulator.mMoveUpTree = false;
 
 				// don't bubble up any ancestors until descendants are done bubbling up
+				// as ancestors may call this timer only on certain paths, so we want to resolve
+				// child-most block locations before their parents
 				it.skipAncestors();
 			}
 		}
-
-		// sort timers by time last called, so call graph makes sense
-		for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer());
-			it != end_timer_tree();
-			++it)
-		{
-			TimeBlock* timerp = (*it);
-			if (timerp->mNeedsSorting)
-			{
-				std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName());
-			}
-			timerp->mNeedsSorting = false;
-		}
 	}
-	
-	//void TimeBlock::accumulateTimings()
-	{
-		U64 cur_time = getCPUClockCount64();
-
-		// root defined by parent pointing to self
-		CurTimerData* cur_data = sCurTimerData.get();
-		// walk up stack of active timers and accumulate current time while leaving timing structures active
-		BlockTimer* cur_timer = cur_data->mCurTimer;
-		TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator();
-		while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer)
-		{
-			U64 cumulative_time_delta = cur_time - cur_timer->mStartTime;
-			U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime;
-			cur_data->mChildTime = 0;
-			accumulator.mSelfTimeCounter += self_time_delta;
-			accumulator.mTotalTimeCounter += cumulative_time_delta;
 
-			cur_timer->mStartTime = cur_time;
+	// walk up stack of active timers and accumulate current time while leaving timing structures active
+	BlockTimer* cur_timer = cur_data->mCurTimer;
+	TimeBlockAccumulator& accumulator = cur_data->mTimerData->getPrimaryAccumulator();
+	// root defined by parent pointing to self
+	while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer)
+	{
+		U64 cumulative_time_delta = cur_time - cur_timer->mStartTime;
+		U64 self_time_delta = cumulative_time_delta - cur_data->mChildTime;
+		cur_data->mChildTime = 0;
+		accumulator.mSelfTimeCounter += self_time_delta;
+		accumulator.mTotalTimeCounter += cumulative_time_delta;
 
-			cur_data = &cur_timer->mLastTimerData;
-			cur_data->mChildTime += cumulative_time_delta;
-			if (cur_data->mTimerData)
-			{
-				accumulator = cur_data->mTimerData->getPrimaryAccumulator();
-			}
+		cur_timer->mStartTime = cur_time;
 
-			cur_timer = cur_timer->mLastTimerData.mCurTimer;
+		cur_data = &cur_timer->mLastTimerData;
+		cur_data->mChildTime += cumulative_time_delta;
+		if (cur_data->mTimerData)
+		{
+			accumulator = cur_data->mTimerData->getPrimaryAccumulator();
 		}
 
-		// traverse tree in DFS post order, or bottom up
-		//for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer());
-		//	it != end_timer_tree_bottom_up();
-		//	++it)
-		//{
-		//	TimeBlock* timerp = (*it);
-		//	TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator();
-		//	timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter;
-		//	for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it)
-		//	{
-		//		timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter;
-		//	}
-
-		//S32 cur_frame = getCurFrameIndex();
-		//if (cur_frame >= 0)
-		//{
-		//	// update timer history
+		cur_timer = cur_timer->mLastTimerData.mCurTimer;
+	}
 
-		//	int hidx = getCurFrameIndex() % HISTORY_NUM;
 
-		//	timerp->mCountHistory[hidx] = timerp->mTreeTimeCounter;
-		//	timerp->mCountAverage       = ((U64)timerp->mCountAverage * cur_frame + timerp->mTreeTimeCounter) / (cur_frame+1);
-		//	timerp->mCallHistory[hidx]  = accumulator.mCalls;
-		//	timerp->mCallAverage        = ((U64)timerp->mCallAverage * cur_frame + accumulator.mCalls) / (cur_frame+1);
-		//}
-		//}
+	// reset for next frame
+	for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(),
+			end_it = LLInstanceTracker<TimeBlock>::endInstances();
+		it != end_it;
+		++it)
+	{
+		TimeBlock& timer = *it;
+		TimeBlockAccumulator& accumulator = timer.getPrimaryAccumulator();
+
+		accumulator.mLastCaller = NULL;
+		accumulator.mMoveUpTree = false;
 	}
+
+	// traverse tree in DFS post order, or bottom up
+	//for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(TimeBlock::getRootTimer());
+	//	it != end_timer_tree_bottom_up();
+	//	++it)
+	//{
+	//	TimeBlock* timerp = (*it);
+	//	TimeBlockAccumulator& accumulator = timerp->getPrimaryAccumulator();
+	//	timerp->mTreeTimeCounter = accumulator.mSelfTimeCounter;
+	//	for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it)
+	//	{
+	//		timerp->mTreeTimeCounter += (*child_it)->mTreeTimeCounter;
+	//	}
+	//}
 }
 
 
@@ -376,106 +354,78 @@ std::vector<TimeBlock*>& TimeBlock::getChildren()
 }
 
 //static
-void TimeBlock::nextFrame()
+void TimeBlock::logStats()
 {
-	get_clock_count(); // good place to calculate clock frequency
-	U64 frame_time = TimeBlock::getCPUClockCount64();
-	if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff)
-	{
-		llinfos << "Slow frame, fast timers inaccurate" << llendl;
-	}
-
-	if (!sPauseHistory)
-	{
-		TimeBlock::processTimes();
-		sLastFrameIndex = sCurFrameIndex++;
-	}
-	
 	// get ready for next frame
-	//void TimeBlock::resetFrame()
-	{
-		if (sLog)
-		{ //output current frame counts to performance log
+	if (sLog)
+	{ //output current frame counts to performance log
 
-			static S32 call_count = 0;
-			if (call_count % 100 == 0)
-			{
-				LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL;
-				LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL;
-				LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL;
-				LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL;
-				LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit<LLUnits::Hertz, F64>(LLProcessorInfo().getCPUFrequency())) << LL_ENDL;
-			}
-			call_count++;
+		static S32 call_count = 0;
+		if (call_count % 100 == 0)
+		{
+			LL_DEBUGS("FastTimers") << "countsPerSecond: " << countsPerSecond() << LL_ENDL;
+			LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL;
+			LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL;
+			LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL;
+			LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64()) / (LLUnit<LLUnits::Hertz, F64>(LLProcessorInfo().getCPUFrequency())) << LL_ENDL;
+		}
+		call_count++;
 
-			LLUnit<LLUnits::Seconds, F64> total_time(0);
-			LLSD sd;
+		LLUnit<LLUnits::Seconds, F64> total_time(0);
+		LLSD sd;
 
+		{
+			for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), 
+				end_it = LLInstanceTracker<TimeBlock>::endInstances(); 
+				it != end_it; 
+			++it)
 			{
-				for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(), 
-					end_it = LLInstanceTracker<TimeBlock>::endInstances(); 
-					it != end_it; 
-				++it)
-				{
-					TimeBlock& timer = *it;
-					LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording();
-					sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecordingPeriod().getSum(timer).value());	
-					sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecordingPeriod().getSum(timer.callCount()));
-
-					// computing total time here because getting the root timer's getCountHistory
-					// doesn't work correctly on the first frame
-					total_time += frame_recording.getLastRecordingPeriod().getSum(timer);
-				}
-			}
-
-			sd["Total"]["Time"] = (LLSD::Real) total_time.value();
-			sd["Total"]["Calls"] = (LLSD::Integer) 1;
+				TimeBlock& timer = *it;
+				LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording();
+				sd[timer.getName()]["Time"] = (LLSD::Real) (frame_recording.getLastRecordingPeriod().getSum(timer).value());	
+				sd[timer.getName()]["Calls"] = (LLSD::Integer) (frame_recording.getLastRecordingPeriod().getSum(timer.callCount()));
 
-			{		
-				LLMutexLock lock(sLogLock);
-				sLogQueue.push(sd);
+				// computing total time here because getting the root timer's getCountHistory
+				// doesn't work correctly on the first frame
+				total_time += frame_recording.getLastRecordingPeriod().getSum(timer);
 			}
 		}
 
-		// reset for next frame
-		for (LLInstanceTracker<TimeBlock>::instance_iter it = LLInstanceTracker<TimeBlock>::beginInstances(),
-			end_it = LLInstanceTracker<TimeBlock>::endInstances();
-			it != end_it;
-		++it)
-		{
-			TimeBlock& timer = *it;
-			TimeBlockTreeNode& tree_node = sCurTimerData->mTimerTreeData[timer.getIndex()];
+		sd["Total"]["Time"] = (LLSD::Real) total_time.value();
+		sd["Total"]["Calls"] = (LLSD::Integer) 1;
 
-			tree_node.mLastCaller = NULL;
-			tree_node.mMoveUpTree = false;
+		{		
+			LLMutexLock lock(sLogLock);
+			sLogQueue.push(sd);
 		}
 	}
-	sLastFrameTime = frame_time;
+
 }
 
 //static
 void TimeBlock::dumpCurTimes()
 {
-	// accumulate timings, etc.
-	processTimes();
-	
+	LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording();
+	LLTrace::Recording& last_frame_recording = frame_recording.getLastRecordingPeriod();
+
 	// walk over timers in depth order and output timings
 	for(timer_tree_dfs_iterator_t it = begin_timer_tree(TimeBlock::getRootTimer());
 		it != end_timer_tree();
 		++it)
 	{
-		LLTrace::PeriodicRecording& frame_recording = LLTrace::get_frame_recording();
 		TimeBlock* timerp = (*it);
-		LLUnit<LLUnits::Seconds, F64> total_time_ms = frame_recording.getLastRecordingPeriod().getSum(*timerp);
-		U32 num_calls = frame_recording.getLastRecordingPeriod().getSum(timerp->callCount());
+		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() << " " 
@@ -505,7 +455,11 @@ void TimeBlock::writeLog(std::ostream& os)
 TimeBlockAccumulator::TimeBlockAccumulator() 
 :	mSelfTimeCounter(0),
 	mTotalTimeCounter(0),
-	mCalls(0)
+	mCalls(0),
+	mLastCaller(NULL),
+	mActiveCount(0),
+	mMoveUpTree(false),
+	mParent(NULL)
 {}
 
 void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other )
@@ -513,6 +467,10 @@ void TimeBlockAccumulator::addSamples( const TimeBlockAccumulator& other )
 	mSelfTimeCounter += other.mSelfTimeCounter;
 	mTotalTimeCounter += other.mTotalTimeCounter;
 	mCalls += other.mCalls;
+	mLastCaller = other.mLastCaller;
+	mActiveCount = other.mActiveCount;
+	mMoveUpTree = other.mMoveUpTree;
+	mParent = other.mParent;
 }
 
 void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other )
@@ -522,10 +480,4 @@ void TimeBlockAccumulator::reset( const TimeBlockAccumulator* other )
 	mCalls = 0;
 }
 
-TimeBlockTreeNode::TimeBlockTreeNode()
-:	mLastCaller(NULL),
-	mActiveCount(0),
-	mMoveUpTree(false)
-{}
-
 } // namespace LLTrace