EXP-1843 WIP Added an option to output avatar rez timing.

Use the new "Avatar Rez" debugging tag to see the output.

9 files changed, 58 insertions, 1 deletions

diff --git a/indra/newview/llagent.cpp b/indra/newview/llagent.cpp
index 54ad3cd187..ab9b5ff436 100755
--- a/indra/newview/llagent.cpp
+++ b/indra/newview/llagent.cpp
@@ -3314,6 +3314,7 @@ void LLAgent::processAgentCachedTextureResponse(LLMessageSystem *mesgsys, void *
 	}
 
 	llinfos << "Received cached texture response for " << num_results << " textures." << llendl;
+	gAgentAvatarp->outputRezTiming("Fetched agent wearables textures from cache. Will now load them");
 
 	gAgentAvatarp->updateMeshTextures();
 
diff --git a/indra/newview/llagentwearables.cpp b/indra/newview/llagentwearables.cpp
index 13b62cb019..09305a5b4d 100644
--- a/indra/newview/llagentwearables.cpp
+++ b/indra/newview/llagentwearables.cpp
@@ -185,6 +185,7 @@ void LLAgentWearables::setAvatarObject(LLVOAvatarSelf *avatar)
 { 
 	if (avatar)
 	{
+		avatar->outputRezTiming("Sending wearables request");
 		sendAgentWearablesRequest();
 	}
 }
@@ -949,6 +950,11 @@ void LLAgentWearables::processAgentInitialWearablesUpdate(LLMessageSystem* mesgs
 	if (mInitialWearablesUpdateReceived)
 		return;
 
+	if (isAgentAvatarValid())
+	{
+		gAgentAvatarp->outputRezTiming("Received initial wearables update");
+	}
+
 	// notify subscribers that wearables started loading. See EXT-7777
 	// *TODO: find more proper place to not be called from deprecated method.
 	// Seems such place is found: LLInitialWearablesFetch::processContents()
@@ -1619,6 +1625,11 @@ void LLAgentWearables::queryWearableCache()
 	//VWR-22113: gAgent.getRegion() can return null if invalid, seen here on logout
 	if(gAgent.getRegion())
 	{
+		if (isAgentAvatarValid())
+		{
+			gAgentAvatarp->outputRezTiming("Fetching textures from cache");
+		}
+
 		llinfos << "Requesting texture cache entry for " << num_queries << " baked textures" << llendl;
 		gMessageSystem->sendReliable(gAgent.getRegion()->getHost());
 		gAgentQueryManager.mNumPendingQueries++;
diff --git a/indra/newview/llagentwearablesfetch.cpp b/indra/newview/llagentwearablesfetch.cpp
index 4097ff707c..8cba54347e 100644
--- a/indra/newview/llagentwearablesfetch.cpp
+++ b/indra/newview/llagentwearablesfetch.cpp
@@ -87,6 +87,10 @@ public:
 LLInitialWearablesFetch::LLInitialWearablesFetch(const LLUUID& cof_id) :
 	LLInventoryFetchDescendentsObserver(cof_id)
 {
+	if (isAgentAvatarValid())
+	{
+		gAgentAvatarp->outputRezTiming("Initial wearables fetch started");
+	}
 }
 
 LLInitialWearablesFetch::~LLInitialWearablesFetch()
@@ -101,6 +105,10 @@ void LLInitialWearablesFetch::done()
 	// idle tick instead.
 	gInventory.removeObserver(this);
 	doOnIdleOneTime(boost::bind(&LLInitialWearablesFetch::processContents,this));
+	if (isAgentAvatarValid())
+	{
+		gAgentAvatarp->outputRezTiming("Initial wearables fetch done");
+	}
 }
 
 void LLInitialWearablesFetch::add(InitialWearableData &data)
diff --git a/indra/newview/llagentwearablesfetch.h b/indra/newview/llagentwearablesfetch.h
index 7dafab4a33..bedc445c0e 100644
--- a/indra/newview/llagentwearablesfetch.h
+++ b/indra/newview/llagentwearablesfetch.h
@@ -40,6 +40,8 @@
 //--------------------------------------------------------------------
 class LLInitialWearablesFetch : public LLInventoryFetchDescendentsObserver
 {
+	LOG_CLASS(LLInitialWearablesFetch);
+
 public:
 	LLInitialWearablesFetch(const LLUUID& cof_id);
 	~LLInitialWearablesFetch();
diff --git a/indra/newview/llappearancemgr.cpp b/indra/newview/llappearancemgr.cpp
index 663257042e..33f5373d7e 100644
--- a/indra/newview/llappearancemgr.cpp
+++ b/indra/newview/llappearancemgr.cpp
@@ -268,6 +268,8 @@ struct LLFoundData
 	
 class LLWearableHoldingPattern
 {
+	LOG_CLASS(LLWearableHoldingPattern);
+
 public:
 	LLWearableHoldingPattern();
 	~LLWearableHoldingPattern();
@@ -436,6 +438,11 @@ void LLWearableHoldingPattern::checkMissingWearables()
 
 void LLWearableHoldingPattern::onAllComplete()
 {
+	if (isAgentAvatarValid())
+	{
+		gAgentAvatarp->outputRezTiming("Agent wearables fetch complete");
+	}
+
 	if (!isMostRecent())
 	{
 		llwarns << "skipping because LLWearableHolding pattern is invalid (superceded by later outfit request)" << llendl;
@@ -2363,6 +2370,8 @@ void LLAppearanceMgr::autopopulateOutfits()
 // Handler for anything that's deferred until avatar de-clouds.
 void LLAppearanceMgr::onFirstFullyVisible()
 {
+	gAgentAvatarp->outputRezTiming("Avatar fully loaded");
+	gAgentAvatarp->reportAvatarRezTime();
 	gAgentAvatarp->debugAvatarVisible();
 
 	// The auto-populate is failing at the point of generating outfits
diff --git a/indra/newview/lltexlayer.h b/indra/newview/lltexlayer.h
index 85dadb213c..4f43547dae 100644
--- a/indra/newview/lltexlayer.h
+++ b/indra/newview/lltexlayer.h
@@ -261,6 +261,8 @@ private:
 //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 class LLTexLayerSetBuffer : public LLViewerDynamicTexture
 {
+	LOG_CLASS(LLTexLayerSetBuffer);
+
 public:
 	LLTexLayerSetBuffer(LLTexLayerSet* const owner, S32 width, S32 height);
 	virtual ~LLTexLayerSetBuffer();
diff --git a/indra/newview/llvoavatar.h b/indra/newview/llvoavatar.h
index 4cd61cecf9..dd0317f555 100644
--- a/indra/newview/llvoavatar.h
+++ b/indra/newview/llvoavatar.h
@@ -78,6 +78,8 @@ class LLVOAvatar :
 	public LLCharacter,
 	public boost::signals2::trackable
 {
+	LOG_CLASS(LLVOAvatar);
+
 public:
 	friend class LLVOAvatarSelf;
 protected:
diff --git a/indra/newview/llvoavatarself.cpp b/indra/newview/llvoavatarself.cpp
index 581912f844..f1df67494f 100644
--- a/indra/newview/llvoavatarself.cpp
+++ b/indra/newview/llvoavatarself.cpp
@@ -1574,7 +1574,7 @@ void LLVOAvatarSelf::invalidateAll()
 	{
 		invalidateComposite(mBakedTextureDatas[i].mTexLayerSet, TRUE);
 	}
-	mDebugSelfLoadTimer.reset();
+	//mDebugSelfLoadTimer.reset();
 }
 
 //-----------------------------------------------------------------------------
@@ -1896,11 +1896,13 @@ BOOL LLVOAvatarSelf::getIsCloud()
 		gAgentWearables.getWearableCount(LLWearableType::WT_EYES) == 0 ||
 		gAgentWearables.getWearableCount(LLWearableType::WT_SKIN) == 0)	
 	{
+		lldebugs << "No body parts" << llendl;
 		return TRUE;
 	}
 
 	if (!isTextureDefined(TEX_HAIR, 0))
 	{
+		lldebugs << "No hair texture" << llendl;
 		return TRUE;
 	}
 
@@ -1909,12 +1911,14 @@ BOOL LLVOAvatarSelf::getIsCloud()
 		if (!isLocalTextureDataAvailable(mBakedTextureDatas[BAKED_LOWER].mTexLayerSet) &&
 			(!isTextureDefined(TEX_LOWER_BAKED, 0)))
 		{
+			lldebugs << "Lower textures not baked" << llendl;
 			return TRUE;
 		}
 
 		if (!isLocalTextureDataAvailable(mBakedTextureDatas[BAKED_UPPER].mTexLayerSet) &&
 			(!isTextureDefined(TEX_UPPER_BAKED, 0)))
 		{
+			lldebugs << "Upper textures not baked" << llendl;
 			return TRUE;
 		}
 
@@ -1931,10 +1935,12 @@ BOOL LLVOAvatarSelf::getIsCloud()
 			const LLViewerTexture* baked_img = getImage( texture_data.mTextureIndex, 0 );
 			if (!baked_img || !baked_img->hasGLTexture())
 			{
+				lldebugs << "Texture at index " << i << " (texture index is " << texture_data.mTextureIndex << ") is not loaded" << llendl;
 				return TRUE;
 			}
 		}
 
+		lldebugs << "Avatar de-clouded" << llendl;
 	}
 	return FALSE;
 }
@@ -2258,6 +2264,7 @@ void LLVOAvatarSelf::setNewBakedTexture( ETextureIndex te, const LLUUID& uuid )
 	}
 }
 
+// FIXME: This is never called. Something may be broken.
 void LLVOAvatarSelf::outputRezDiagnostics() const
 {
 	if(!gSavedSettings.getBOOL("DebugAvatarLocalTexLoadedTime"))
@@ -2315,6 +2322,18 @@ void LLVOAvatarSelf::outputRezDiagnostics() const
 	}
 }
 
+void LLVOAvatarSelf::outputRezTiming(const std::string& msg) const
+{
+	LL_DEBUGS("Avatar Rez")
+		<< llformat("%s. Time from avatar creation: %.2f", msg.c_str(), mDebugSelfLoadTimer.getElapsedTimeF32())
+		<< llendl;
+}
+
+void LLVOAvatarSelf::reportAvatarRezTime() const
+{
+	// TODO: report mDebugSelfLoadTimer.getElapsedTimeF32() somehow.
+}
+
 //-----------------------------------------------------------------------------
 // setCachedBakedTexture()
 // A baked texture id was received from a cache query, make it active
diff --git a/indra/newview/llvoavatarself.h b/indra/newview/llvoavatarself.h
index 74ff47a3e4..54dbe81993 100644
--- a/indra/newview/llvoavatarself.h
+++ b/indra/newview/llvoavatarself.h
@@ -41,6 +41,7 @@ struct LocalTextureData;
 class LLVOAvatarSelf :
 	public LLVOAvatar
 {
+	LOG_CLASS(LLVOAvatarSelf);
 
 /********************************************************************************
  **                                                                            **
@@ -358,6 +359,8 @@ public:
 	void 					debugWearablesLoaded() { mDebugTimeWearablesLoaded = mDebugSelfLoadTimer.getElapsedTimeF32(); }
 	void 					debugAvatarVisible() { mDebugTimeAvatarVisible = mDebugSelfLoadTimer.getElapsedTimeF32(); }
 	void 					outputRezDiagnostics() const;
+	void					outputRezTiming(const std::string& msg) const;
+	void					reportAvatarRezTime() const;
 	void 					debugBakedTextureUpload(LLVOAvatarDefines::EBakedTextureIndex index, BOOL finished);
 	static void				debugOnTimingLocalTexLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata);