SH-3852 WIP - track per-timer stats

11 files changed, 164 insertions, 53 deletions

diff --git a/indra/newview/llagent.cpp b/indra/newview/llagent.cpp
index abd83485af..c86b75791d 100755
--- a/indra/newview/llagent.cpp
+++ b/indra/newview/llagent.cpp
@@ -4338,12 +4338,10 @@ void LLAgent::sendAgentSetAppearance()
 	if (!gAgentWearables.changeInProgress())
 	{
 		// Change is fully resolved, can close some open phases.
-		gAgentAvatarp->getPhases().stopPhase("process_initial_wearables_update");
-		gAgentAvatarp->getPhases().stopPhase("wear_inventory_category");
+		gAgentAvatarp->stopPhase("process_initial_wearables_update");
+		gAgentAvatarp->stopPhase("wear_inventory_category");
 	}
 
-	gAgentAvatarp->sendAppearanceChangeMetrics();
-
 	if (!isAgentAvatarValid() || (getRegion() && getRegion()->getCentralBakeVersion())) return;
 
 	// At this point we have a complete appearance to send and are in a non-baking region.
diff --git a/indra/newview/llagentwearables.cpp b/indra/newview/llagentwearables.cpp
index 70f4de8db2..0c79ac0ba3 100755
--- a/indra/newview/llagentwearables.cpp
+++ b/indra/newview/llagentwearables.cpp
@@ -797,7 +797,7 @@ void LLAgentWearables::processAgentInitialWearablesUpdate(LLMessageSystem* mesgs
 	if (isAgentAvatarValid())
 	{
 		//gAgentAvatarp->clearPhases(); // reset phase timers for outfit loading.
-		gAgentAvatarp->getPhases().startPhase("process_initial_wearables_update");
+		gAgentAvatarp->startPhase("process_initial_wearables_update");
 		gAgentAvatarp->outputRezTiming("Received initial wearables update");
 	}
 
diff --git a/indra/newview/llagentwearablesfetch.cpp b/indra/newview/llagentwearablesfetch.cpp
index 2d622b380a..6f1658d1cc 100644
--- a/indra/newview/llagentwearablesfetch.cpp
+++ b/indra/newview/llagentwearablesfetch.cpp
@@ -80,7 +80,7 @@ LLInitialWearablesFetch::LLInitialWearablesFetch(const LLUUID& cof_id) :
 {
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->getPhases().startPhase("initial_wearables_fetch");
+		gAgentAvatarp->startPhase("initial_wearables_fetch");
 		gAgentAvatarp->outputRezTiming("Initial wearables fetch started");
 	}
 }
@@ -99,7 +99,7 @@ void LLInitialWearablesFetch::done()
 	doOnIdleOneTime(boost::bind(&LLInitialWearablesFetch::processContents,this));
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->getPhases().stopPhase("initial_wearables_fetch");
+		gAgentAvatarp->stopPhase("initial_wearables_fetch");
 		gAgentAvatarp->outputRezTiming("Initial wearables fetch done");
 	}
 }
diff --git a/indra/newview/llappearancemgr.cpp b/indra/newview/llappearancemgr.cpp
index f1ba4ad453..1a6d49c7a2 100755
--- a/indra/newview/llappearancemgr.cpp
+++ b/indra/newview/llappearancemgr.cpp
@@ -2006,8 +2006,6 @@ void LLAppearanceMgr::updateAppearanceFromCOF(bool update_base_outfit_ordering)
 		llwarns << "Called updateAppearanceFromCOF inside updateAppearanceFromCOF, skipping" << llendl;
 		return;
 	}
-
-	LLVOAvatar::ScopedPhaseSetter(gAgentAvatarp,"update_appearance_from_cof");
 	
 	BoolSetter setIsInUpdateAppearanceFromCOF(mIsInUpdateAppearanceFromCOF);
 
diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp
index 03b11939a9..2ee325a09e 100644..100755
--- a/indra/newview/llappviewer.cpp
+++ b/indra/newview/llappviewer.cpp
@@ -3612,6 +3612,12 @@ void LLAppViewer::requestQuit()
 
 	// Try to send metrics back to the grid
 	metricsSend(!gDisconnected);
+
+	// Try to send last batch of avatar rez metrics.
+	if (!gDisconnected && isAgentAvatarValid())
+	{
+		gAgentAvatarp->updateAvatarRezMetrics(true); // force a last packet to be sent.
+	}
 	
 	LLHUDEffectSpiral *effectp = (LLHUDEffectSpiral*)LLHUDManager::getInstance()->createViewerEffect(LLHUDObject::LL_HUD_EFFECT_POINT, TRUE);
 	effectp->setPositionGlobal(gAgent.getPositionGlobal());
diff --git a/indra/newview/llviewerstats.cpp b/indra/newview/llviewerstats.cpp
index bccd4c1a60..28c6b59391 100755
--- a/indra/newview/llviewerstats.cpp
+++ b/indra/newview/llviewerstats.cpp
@@ -733,6 +733,10 @@ void send_stats()
 	LLHTTPClient::post(url, body, new ViewerStatsResponder());
 }
 
+LLViewerStats::PhaseMap::PhaseMap()
+{
+}
+
 LLTimer& LLViewerStats::PhaseMap::getPhaseTimer(const std::string& phase_name)
 {
 	phase_map_t::iterator iter = mPhaseMap.find(phase_name);
@@ -761,32 +765,26 @@ void LLViewerStats::PhaseMap::stopPhase(const std::string& phase_name)
 		{
 			// Going from started to paused state - record stats.
 			recordPhaseStat(phase_name,iter->second.getElapsedTimeF32());
+			iter->second.stop();
 		}
-		lldebugs << "stopPhase " << phase_name << llendl;
-		iter->second.stop();
-	}
-	else
-	{
-		lldebugs << "stopPhase " << phase_name << " is not started, no-op" << llendl;
 	}
 }
 
-void LLViewerStats::PhaseMap::stopAllPhases()
+bool LLViewerStats::PhaseMap::getPhaseValues(const std::string& phase_name, F32& elapsed, bool& completed)
 {
-	for (phase_map_t::iterator iter = mPhaseMap.begin();
-		 iter != mPhaseMap.end(); ++iter)
+	phase_map_t::iterator iter = mPhaseMap.find(phase_name);
+	if (iter != mPhaseMap.end())
 	{
-		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.stop();
+		elapsed =  iter->second.getElapsedTimeF32();
+		completed = !iter->second.getStarted();
+		return true;
+	}
+	else
+	{
+		return false;
 	}
 }
-
+	
 void LLViewerStats::PhaseMap::clearPhases()
 {
 	lldebugs << "clearPhases" << llendl;
@@ -810,10 +808,6 @@ LLSD LLViewerStats::PhaseMap::dumpPhases()
 //static
 LLViewerStats::phase_stats_t LLViewerStats::PhaseMap::sStats;
 
-LLViewerStats::PhaseMap::PhaseMap()
-{
-}
-
 // static
 LLViewerStats::StatsAccumulator& LLViewerStats::PhaseMap::getPhaseStats(const std::string& phase_name)
 {
diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h
index bb11e8c5be..084f5ae7d1 100755
--- a/indra/newview/llviewerstats.h
+++ b/indra/newview/llviewerstats.h
@@ -289,13 +289,15 @@ public:
 	public:
 		PhaseMap();
 		LLTimer&	 	getPhaseTimer(const std::string& phase_name);
+		bool 			getPhaseValues(const std::string& phase_name, F32& elapsed, bool& completed);
 		void			startPhase(const std::string& phase_name);
 		void			stopPhase(const std::string& phase_name);
-		void			stopAllPhases();
 		void			clearPhases();
 		LLSD			dumpPhases();
 		static StatsAccumulator& getPhaseStats(const std::string& phase_name);
 		static void recordPhaseStat(const std::string& phase_name, F32 value);
+		phase_map_t::iterator begin() { return mPhaseMap.begin(); }
+		phase_map_t::iterator end() { return mPhaseMap.end(); }
 	};
 
 private:
diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp
index 483bc25b33..f7e1944660 100755
--- a/indra/newview/llvoavatar.cpp
+++ b/indra/newview/llvoavatar.cpp
@@ -5887,30 +5887,123 @@ void LLVOAvatar::updateRezzedStatusTimers()
 		if (is_cloud && !was_cloud)
 		{
 			// start cloud timer.
-			getPhases().startPhase("cloud");
+			startPhase("cloud");
 		}
 		else if (was_cloud && !is_cloud)
 		{
 			// stop cloud timer, which will capture stats.
-			getPhases().stopPhase("cloud");
+			stopPhase("cloud");
 		}
 
 		// Non-cloud-or-gray to cloud-or-gray
 		if (is_cloud_or_gray && !was_cloud_or_gray)
 		{
 			// start cloud-or-gray timer.
-			getPhases().startPhase("cloud-or-gray");
+			startPhase("cloud-or-gray");
 		}
 		else if (was_cloud_or_gray && !is_cloud_or_gray)
 		{
 			// stop cloud-or-gray timer, which will capture stats.
-			getPhases().stopPhase("cloud-or-gray");
+			stopPhase("cloud-or-gray");
 		}
 		
 		mLastRezzedStatus = rez_status;
 	}
 }
 
+void LLVOAvatar::clearPhases()
+{
+	getPhases().clearPhases();
+}
+
+void LLVOAvatar::startPhase(const std::string& phase_name)
+{
+	getPhases().startPhase(phase_name);
+}
+
+void LLVOAvatar::logPendingPhases()
+{
+	for (LLViewerStats::phase_map_t::iterator it = getPhases().begin();
+		 it != getPhases().end();
+		 ++it)
+	{
+		const std::string& phase_name = it->first;
+		F32 elapsed;
+		bool completed;
+		if (getPhases().getPhaseValues(phase_name, elapsed, completed))
+		{
+			if (!completed)
+			{
+				logMetricsTimerRecord(phase_name, elapsed, completed);
+			}
+			else
+			{
+				llwarns << "ignoring " << phase_name << llendl;
+			}
+		}
+	}
+}
+
+//static
+void LLVOAvatar::logPendingPhasesAllAvatars()
+{
+	for (std::vector<LLCharacter*>::iterator iter = LLCharacter::sInstances.begin();
+		 iter != LLCharacter::sInstances.end(); ++iter)
+	{
+		LLVOAvatar* inst = (LLVOAvatar*) *iter;
+		if( inst->isDead() )
+		{
+			continue;
+		}
+		inst->logPendingPhases();
+	}
+}
+
+void LLVOAvatar::logMetricsTimerRecord(const std::string& phase_name, F32 elapsed, bool completed)
+{
+	LLSD record;
+	record["timer_name"] = phase_name;
+	record["agent_id"] = gAgent.getID();
+	record["elapsed"] = elapsed;
+	record["completed"] = completed;
+	U32 grid_x(0), grid_y(0);
+	if (getRegion())
+	{
+		record["cbv"] = getRegion()->getCentralBakeVersion();
+		grid_from_region_handle(getRegion()->getHandle(), &grid_x, &grid_y);
+	}
+	record["grid_x"] = LLSD::Integer(grid_x);
+	record["grid_y"] = LLSD::Integer(grid_y);
+	record["is_using_server_bake"] = isUsingServerBakes();
+	record["is_self"] = isSelf();
+	
+	LL_DEBUGS("Avatar") << "record\n" << ll_pretty_print_sd(record) << llendl;
+}
+
+void LLVOAvatar::stopPhase(const std::string& phase_name)
+{
+	F32 elapsed;
+	bool completed;
+	if (getPhases().getPhaseValues(phase_name, elapsed, completed))
+	{
+		if (!completed)
+		{
+			getPhases().stopPhase(phase_name);
+			completed = true;
+
+		}
+		else
+		{
+			llwarns << "stop when stopped already for " << phase_name << llendl;
+		}
+		logMetricsTimerRecord(phase_name, elapsed, completed);
+	}
+	else
+	{
+		llwarns << "stop when not started for " << phase_name << llendl;
+	}
+}
+
 // call periodically to keep isFullyLoaded up to date.
 // returns true if the value has changed.
 BOOL LLVOAvatar::updateIsFullyLoaded()
diff --git a/indra/newview/llvoavatar.h b/indra/newview/llvoavatar.h
index c14f18d00e..8babcc3ef3 100755
--- a/indra/newview/llvoavatar.h
+++ b/indra/newview/llvoavatar.h
@@ -292,12 +292,16 @@ public:
 
 	S32				mLastRezzedStatus;
 
-	LLViewerStats::PhaseMap& getPhases()
-	{
-		return mPhases;
-	}
+	
+	void 			startPhase(const std::string& phase_name);
+	void 			stopPhase(const std::string& phase_name);
+	void			clearPhases();
+	void 			logPendingPhases();
+	static void 	logPendingPhasesAllAvatars();
+	void 			logMetricsTimerRecord(const std::string& phase_name, F32 elapsed, bool completed);
 
 protected:
+	LLViewerStats::PhaseMap& getPhases() { return mPhases; }
 	BOOL			updateIsFullyLoaded();
 	BOOL			processFullyLoadedChange(bool loading);
 	void			updateRuthTimer(bool loading);
diff --git a/indra/newview/llvoavatarself.cpp b/indra/newview/llvoavatarself.cpp
index a1c7cf97ff..3ae4f9bc71 100755
--- a/indra/newview/llvoavatarself.cpp
+++ b/indra/newview/llvoavatarself.cpp
@@ -81,7 +81,7 @@ void selfStartPhase(const std::string& phase_name)
 {
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->getPhases().startPhase(phase_name);
+		gAgentAvatarp->startPhase(phase_name);
 	}
 }
 
@@ -89,7 +89,7 @@ void selfStopPhase(const std::string& phase_name)
 {
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->getPhases().stopPhase(phase_name);
+		gAgentAvatarp->stopPhase(phase_name);
 	}
 }
 
@@ -97,19 +97,11 @@ void selfClearPhases()
 {
 	if (isAgentAvatarValid())
 	{
-		gAgentAvatarp->getPhases().clearPhases();
+		gAgentAvatarp->clearPhases();
 		gAgentAvatarp->mLastRezzedStatus = -1;
 	}
 }
 
-void selfStopAllPhases()
-{
-	if (isAgentAvatarValid())
-	{
-		gAgentAvatarp->getPhases().stopAllPhases();
-	}
-}
-
 using namespace LLAvatarAppearanceDefines;
 
 /*********************************************************************************
@@ -222,6 +214,7 @@ void LLVOAvatarSelf::initInstance()
 	}
 
 	//doPeriodically(output_self_av_texture_diagnostics, 30.0);
+	doPeriodically(boost::bind(&LLVOAvatarSelf::updateAvatarRezMetrics, this, false), 5.0);
 }
 
 // virtual
@@ -2238,6 +2231,22 @@ private:
 	volatile bool & mReportingStarted;
 };
 
+bool LLVOAvatarSelf::updateAvatarRezMetrics(bool force_send)
+{
+	F32 send_period = 30.0;
+
+	if (force_send || mTimeSinceLastRezMessage.getElapsedTimeF32() > send_period)
+	{
+		// Stats for completed phases have been getting logged as they
+		// complete.  This will give us stats for any timers that
+		// haven't finished as of the metric's being sent.
+		LLVOAvatar::logPendingPhasesAllAvatars();
+		sendAppearanceChangeMetrics();
+	}
+
+	return false;
+}
+
 void LLVOAvatarSelf::sendAppearanceChangeMetrics()
 {
 	// gAgentAvatarp->stopAllPhases();
@@ -2251,7 +2260,9 @@ void LLVOAvatarSelf::sendAppearanceChangeMetrics()
 	msg["sequence"] = report_sequence;
 	msg["initial"] = !reporting_started;
 	msg["break"] = false;
-
+	msg["duration"] = mTimeSinceLastRezMessage.getElapsedTimeF32();
+	mTimeSinceLastRezMessage.reset();
+	
 	// Update sequence number
 	if (S32_MAX == ++report_sequence)
 		report_sequence = 0;
diff --git a/indra/newview/llvoavatarself.h b/indra/newview/llvoavatarself.h
index 74888e470d..857c482f93 100755
--- a/indra/newview/llvoavatarself.h
+++ b/indra/newview/llvoavatarself.h
@@ -379,6 +379,10 @@ public:
 		LLUUID			mAvatarID;
 		LLAvatarAppearanceDefines::ETextureIndex	mIndex;
 	};
+
+	LLTimer					mTimeSinceLastRezMessage;
+	bool					updateAvatarRezMetrics(bool force_send);
+	
 	void 					debugWearablesLoaded() { mDebugTimeWearablesLoaded = mDebugSelfLoadTimer.getElapsedTimeF32(); }
 	void 					debugAvatarVisible() { mDebugTimeAvatarVisible = mDebugSelfLoadTimer.getElapsedTimeF32(); }
 	void 					outputRezDiagnostics() const;
@@ -416,7 +420,8 @@ BOOL isAgentAvatarValid();
 
 void selfStartPhase(const std::string& phase_name);
 void selfStopPhase(const std::string& phase_name);
-void selfStopAllPhases();
 void selfClearPhases();
 
+void update_avatar_rez_metrics(bool force_send);
+
 #endif // LL_VO_AVATARSELF_H