SH-3064 WIP - accumulate stats tied to phase timers

5 files changed, 116 insertions, 21 deletions

diff --git a/indra/newview/llagentwearables.cpp b/indra/newview/llagentwearables.cpp
index 843fe8ef5e..5bfcace707 100755
--- a/indra/newview/llagentwearables.cpp
+++ b/indra/newview/llagentwearables.cpp
@@ -952,7 +952,7 @@ void LLAgentWearables::processAgentInitialWearablesUpdate(LLMessageSystem* mesgs
 
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->clearPhases(); // reset phase timers for outfit loading.
+		//gAgentAvatarp->clearPhases(); // reset phase timers for outfit loading.
 		gAgentAvatarp->startPhase("process_initial_wearables_update");
 		gAgentAvatarp->outputRezTiming("Received initial wearables update");
 	}
diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h
index f91a1241fe..718fabc75a 100644..100755
--- a/indra/newview/llviewerstats.h
+++ b/indra/newview/llviewerstats.h
@@ -244,7 +244,7 @@ public:
 		inline F32 getStdDev() const
 		{
 			const F32 mean = getMean();
-			return (mCount == 0) ? 0.f : sqrt( mSumOfSquares/mCount - (mean * mean) );
+			return (mCount < 2) ? 0.f : sqrt(llmax(0.f,mSumOfSquares/mCount - (mean * mean)));
 		}
 		
 		inline U32 getCount() const
diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp
index 58cabd1a24..abbe25175a 100755
--- a/indra/newview/llvoavatar.cpp
+++ b/indra/newview/llvoavatar.cpp
@@ -633,11 +633,11 @@ F32 LLVOAvatar::sLODFactor = 1.f;
 F32 LLVOAvatar::sPhysicsLODFactor = 1.f;
 BOOL LLVOAvatar::sUseImpostors = FALSE;
 BOOL LLVOAvatar::sJointDebug = FALSE;
-
 F32 LLVOAvatar::sUnbakedTime = 0.f;
 F32 LLVOAvatar::sUnbakedUpdateTime = 0.f;
 F32 LLVOAvatar::sGreyTime = 0.f;
 F32 LLVOAvatar::sGreyUpdateTime = 0.f;
+LLVOAvatar::phase_stats_t LLVOAvatar::sPhaseStats;
 
 //-----------------------------------------------------------------------------
 // Helper functions
@@ -696,7 +696,9 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id,
 	mSupportsAlphaLayers(FALSE),
 	mLoadedCallbacksPaused(FALSE),
 	mHasPelvisOffset( FALSE ),
-	mRenderUnloadedAvatar(LLCachedControl<bool>(gSavedSettings, "RenderUnloadedAvatar"))
+	mRenderUnloadedAvatar(LLCachedControl<bool>(gSavedSettings, "RenderUnloadedAvatar")),
+	mLastRezzedStatus(-1)
+
 {
 	LLMemType mt(LLMemType::MTYPE_AVATAR);
 	//VTResume();  // VTune
@@ -793,12 +795,6 @@ void LLVOAvatar::debugAvatarRezTime(std::string notification_name, std::string c
 			<< " : " << comment
 			<< llendl;
 
-	if (gAgentAvatarp && !gAgentAvatarp->isDead()) // not safe to call during ~LLVOAvatarself
-	{
-		LLSD metrics = gAgentAvatarp->metricsData();
-		LL_DEBUGS("Avatar") << gAgentAvatarp->avString() << " metrics " << ll_pretty_print_sd(metrics) << LL_ENDL;
-	}
-
 	if (gSavedSettings.getBOOL("DebugAvatarRezTime"))
 	{
 		LLSD args;
@@ -970,6 +966,7 @@ LLFrameTimer& LLVOAvatar::getPhaseTimer(const std::string& phase_name)
 void LLVOAvatar::startPhase(const std::string& phase_name)
 {
 	LLFrameTimer& timer = getPhaseTimer(phase_name);
+	lldebugs << "startPhase " << phase_name << llendl;
 	timer.unpause();
 }
 
@@ -978,8 +975,18 @@ void LLVOAvatar::stopPhase(const std::string& phase_name)
 	phase_map_t::iterator iter = mPhases.find(phase_name);
 	if (iter != mPhases.end())
 	{
+		if (iter->second.getStarted())
+		{
+			// Going from started to paused state - record stats.
+			recordPhaseStat(phase_name,iter->second.getElapsedTimeF32());
+		}
+		lldebugs << "stopPhase " << phase_name << llendl;
 		iter->second.pause();
 	}
+	else
+	{
+		lldebugs << "stopPhase " << phase_name << " is not started, no-op" << llendl;
+	}
 }
 
 void LLVOAvatar::stopAllPhases()
@@ -987,13 +994,23 @@ void LLVOAvatar::stopAllPhases()
 	for (phase_map_t::iterator iter = mPhases.begin();
 		 iter != mPhases.end(); ++iter)
 	{
+		const std::string& phase_name = iter->first;
+		if (iter->second.getStarted())
+		{
+			// Going from started to paused state - record stats.
+			recordPhaseStat(phase_name,iter->second.getElapsedTimeF32());
+		}
+		lldebugs << "stopPhase (all) " << phase_name << llendl;
 		iter->second.pause();
 	}
 }
 
 void LLVOAvatar::clearPhases()
 {
+	lldebugs << "clearPhases" << llendl;
+
 	mPhases.clear();
+	mLastRezzedStatus = -1;
 }
 
 LLSD LLVOAvatar::dumpPhases()
@@ -1001,12 +1018,39 @@ LLSD LLVOAvatar::dumpPhases()
 	LLSD result;
 	for (phase_map_t::iterator iter = mPhases.begin(); iter != mPhases.end(); ++iter)
 	{
-		result[iter->first]["completed"] = !(iter->second.getStarted());
-		result[iter->first]["elapsed"] = iter->second.getElapsedTimeF32();
+		const std::string& phase_name = iter->first;
+		result[phase_name]["completed"] = !(iter->second.getStarted());
+		result[phase_name]["elapsed"] = iter->second.getElapsedTimeF32();
+#if 0 // global stats for each phase seem like overkill here
+		phase_stats_t::iterator stats_iter = sPhaseStats.find(phase_name);
+		if (stats_iter != sPhaseStats.end())
+		{
+			result[phase_name]["stats"] = stats_iter->second.getData();
+		}
+#endif
 	}
 	return result;
 }
 
+// static
+LLViewerStats::StatsAccumulator& LLVOAvatar::getPhaseStats(const std::string& phase_name)
+{
+	phase_stats_t::iterator it = sPhaseStats.find(phase_name);
+	if (it == sPhaseStats.end())
+	{
+		LLViewerStats::StatsAccumulator new_stats;
+		sPhaseStats[phase_name] = new_stats;
+	}
+	return sPhaseStats[phase_name];
+}
+
+// static
+void LLVOAvatar::recordPhaseStat(const std::string& phase_name, F32 value)
+{
+	LLViewerStats::StatsAccumulator& stats = getPhaseStats(phase_name);
+	stats.push(value);
+}
+
 void LLVOAvatar::deleteLayerSetCaches(bool clearAll)
 {
 	for (U32 i = 0; i < mBakedTextureDatas.size(); i++)
@@ -6544,11 +6588,53 @@ BOOL LLVOAvatar::getIsCloud() const
 	return FALSE;
 }
 
+void LLVOAvatar::updateRezzedStatusTimers()
+{
+	// State machine for rezzed status. Statuses are 0 = cloud, 1 = gray, 2 = textured.
+	// Purpose is to collect time data for each period of cloud or cloud+gray.
+	S32 rez_status = getRezzedStatus();
+	if (rez_status != mLastRezzedStatus)
+	{
+		llinfos << avString() << "zxx rez state change: " << mLastRezzedStatus << " -> " << rez_status << llendl;
+		bool is_cloud_or_gray = (rez_status==0 || rez_status==1);
+		bool was_cloud_or_gray = (mLastRezzedStatus==0 || mLastRezzedStatus==1);
+		bool is_cloud = (rez_status==0);
+		bool was_cloud = (mLastRezzedStatus==0);
+
+		// Non-cloud to cloud
+		if (is_cloud && !was_cloud)
+		{
+			// start cloud timer.
+			startPhase("cloud");
+		}
+		else if (was_cloud && !is_cloud)
+		{
+			// stop cloud timer, which will capture stats.
+			stopPhase("cloud");
+		}
+
+		// Non-cloud-or-gray to cloud-or-gray
+		if (is_cloud_or_gray && !was_cloud_or_gray)
+		{
+			// start cloud-or-gray timer.
+			startPhase("cloud-or-gray");
+		}
+		else if (was_cloud_or_gray && !is_cloud_or_gray)
+		{
+			// stop cloud-or-gray timer, which will capture stats.
+			stopPhase("cloud-or-gray");
+		}
+		
+		mLastRezzedStatus = rez_status;
+	}
+}
+
 // call periodically to keep isFullyLoaded up to date.
 // returns true if the value has changed.
 BOOL LLVOAvatar::updateIsFullyLoaded()
 {
 	const BOOL loading = getIsCloud();
+	updateRezzedStatusTimers();
 	updateRuthTimer(loading);
 	return processFullyLoadedChange(loading);
 }
diff --git a/indra/newview/llvoavatar.h b/indra/newview/llvoavatar.h
index 04ef8d2014..7a1b780862 100755
--- a/indra/newview/llvoavatar.h
+++ b/indra/newview/llvoavatar.h
@@ -48,6 +48,7 @@
 #include "lltexglobalcolor.h"
 #include "lldriverparam.h"
 #include "material_codes.h"		// LL_MCODE_END
+#include "llviewerstats.h"
 
 extern const LLUUID ANIM_AGENT_BODY_NOISE;
 extern const LLUUID ANIM_AGENT_BREATHE_ROT;
@@ -282,6 +283,9 @@ public:
 	BOOL			isFullyTextured() const;
 	BOOL			hasGray() const; 
 	S32				getRezzedStatus() const; // 0 = cloud, 1 = gray, 2 = fully textured.
+	void			updateRezzedStatusTimers();
+
+	S32				mLastRezzedStatus;
 
 	// Tracking progress of active/completed phases for activities like outfit changing.
 	LLFrameTimer& 	getPhaseTimer(const std::string& phase_name);
@@ -290,6 +294,8 @@ public:
 	void			stopAllPhases();
 	void			clearPhases();
 	LLSD			dumpPhases();
+	static LLViewerStats::StatsAccumulator& getPhaseStats(const std::string& phase_name);
+	static void			recordPhaseStat(const std::string& phase_name, F32 value);
 
 	class ScopedPhaseSetter
 	{
@@ -323,8 +329,11 @@ private:
 	LLFrameTimer	mFullyLoadedTimer;
 	LLFrameTimer	mRuthTimer;
 
+	// TODO move all the phase stuff to its down data structure.
 	typedef std::map<std::string,LLFrameTimer>	phase_map_t;
 	phase_map_t		mPhases;
+	typedef std::map<std::string,LLViewerStats::StatsAccumulator>	phase_stats_t;
+	static phase_stats_t	sPhaseStats;
 
 protected:
 	LLFrameTimer    mInvisibleTimer;
diff --git a/indra/newview/llvoavatarself.cpp b/indra/newview/llvoavatarself.cpp
index c593481b40..5ba5ec8ef5 100755
--- a/indra/newview/llvoavatarself.cpp
+++ b/indra/newview/llvoavatarself.cpp
@@ -2430,11 +2430,11 @@ void LLVOAvatarSelf::outputRezDiagnostics() const
 	}
 
 	const F32 final_time = mDebugSelfLoadTimer.getElapsedTimeF32();
-	llinfos << "REZTIME: Myself rez stats:" << llendl;
-	llinfos << "\t Time from avatar creation to load wearables: " << (S32)mDebugTimeWearablesLoaded << llendl;
-	llinfos << "\t Time from avatar creation to de-cloud: " << (S32)mDebugTimeAvatarVisible << llendl;
-	llinfos << "\t Time from avatar creation to de-cloud for others: " << (S32)final_time << llendl;
-	llinfos << "\t Load time for each texture: " << llendl;
+	LL_DEBUGS("Avatar") << "REZTIME: Myself rez stats:" << llendl;
+	LL_DEBUGS("Avatar") << "\t Time from avatar creation to load wearables: " << (S32)mDebugTimeWearablesLoaded << llendl;
+	LL_DEBUGS("Avatar") << "\t Time from avatar creation to de-cloud: " << (S32)mDebugTimeAvatarVisible << llendl;
+	LL_DEBUGS("Avatar") << "\t Time from avatar creation to de-cloud for others: " << (S32)final_time << llendl;
+	LL_DEBUGS("Avatar") << "\t Load time for each texture: " << llendl;
 	for (U32 i = 0; i < LLVOAvatarDefines::TEX_NUM_INDICES; ++i)
 	{
 		std::stringstream out;
@@ -2458,12 +2458,12 @@ void LLVOAvatarSelf::outputRezDiagnostics() const
 
 		// Don't print out non-existent textures.
 		if (j != 0)
-			llinfos << out.str() << llendl;
+			LL_DEBUGS("Avatar") << out.str() << llendl;
 	}
-	llinfos << "\t Time points for each upload (start / finish)" << llendl;
+	LL_DEBUGS("Avatar") << "\t Time points for each upload (start / finish)" << llendl;
 	for (U32 i = 0; i < LLVOAvatarDefines::BAKED_NUM_INDICES; ++i)
 	{
-		llinfos << "\t\t (" << i << ") \t" << (S32)mDebugBakedTextureTimes[i][0] << " / " << (S32)mDebugBakedTextureTimes[i][1] << llendl;
+		LL_DEBUGS("Avatar") << "\t\t (" << i << ") \t" << (S32)mDebugBakedTextureTimes[i][0] << " / " << (S32)mDebugBakedTextureTimes[i][1] << llendl;
 	}
 
 	for (LLVOAvatarDefines::LLVOAvatarDictionary::BakedTextures::const_iterator baked_iter = LLVOAvatarDefines::LLVOAvatarDictionary::getInstance()->getBakedTextures().begin();
@@ -2475,7 +2475,7 @@ void LLVOAvatarSelf::outputRezDiagnostics() const
 		if (!layerset) continue;
 		const LLTexLayerSetBuffer *layerset_buffer = layerset->getComposite();
 		if (!layerset_buffer) continue;
-		llinfos << layerset_buffer->dumpTextureInfo() << llendl;
+		LL_DEBUGS("Avatar") << layerset_buffer->dumpTextureInfo() << llendl;
 	}
 }