adding verbose logging around your own avatar rez time. Documents load times

for each component texture at each discard level, as well as baked texture
upload times, and reports the timing of each texture to the console when your
avatar sends out its appearance data to the server.

Reviewed by Seraph, will be removed before release.

 -Nyx

6 files changed, 91 insertions, 12 deletions

diff --git a/indra/newview/llappearancemgr.cpp b/indra/newview/llappearancemgr.cpp
index be840cc348..4aef72ab0b 100644
--- a/indra/newview/llappearancemgr.cpp
+++ b/indra/newview/llappearancemgr.cpp
@@ -524,6 +524,7 @@ bool LLWearableHoldingPattern::pollMissingWearables()
 
 	if (done)
 	{
+		gAgentAvatarp->wearablesLoaded();
 		clearCOFLinksForMissingWearables();
 		onAllComplete();
 	}
@@ -1649,6 +1650,7 @@ void LLAppearanceMgr::autopopulateOutfits()
 // Handler for anything that's deferred until avatar de-clouds.
 void LLAppearanceMgr::onFirstFullyVisible()
 {
+	gAgentAvatarp->avatarVisible();
 	autopopulateOutfits();
 }
 
diff --git a/indra/newview/lltexlayer.cpp b/indra/newview/lltexlayer.cpp
index 82fa672342..337627cc79 100644
--- a/indra/newview/lltexlayer.cpp
+++ b/indra/newview/lltexlayer.cpp
@@ -237,6 +237,7 @@ BOOL LLTexLayerSetBuffer::render()
 		{
 			if (mTexLayerSet->isVisible())
 			{
+				mTexLayerSet->getAvatar()->bakedTextureUpload(mTexLayerSet->getBakedTexIndex(), FALSE); // FALSE for start of upload, TRUE for finish.
 				readBackAndUpload();
 			}
 			else
diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp
index 2ec8ced543..c64f7b5a3e 100644
--- a/indra/newview/llvoavatar.cpp
+++ b/indra/newview/llvoavatar.cpp
@@ -5869,14 +5869,14 @@ void LLVOAvatar::updateRuthTimer(bool loading)
 	const F32 LOADING_TIMEOUT = 120.f;
 	if (mRuthTimer.getElapsedTimeF32() > LOADING_TIMEOUT)
 	{
-		/*
+		
 		llinfos << "Ruth Timer timeout: Missing texture data for '" << getFullname() << "' "
 				<< "( Params loaded : " << !visualParamWeightsAreDefault() << " ) "
 				<< "( Lower : " << isTextureDefined(TEX_LOWER_BAKED) << " ) "
 				<< "( Upper : " << isTextureDefined(TEX_UPPER_BAKED) << " ) "
 				<< "( Head : " << isTextureDefined(TEX_HEAD_BAKED) << " )."
 				<< llendl;
-		*/
+		
 		LLAvatarPropertiesProcessor::getInstance()->sendAvatarTexturesRequest(getID());
 		mRuthTimer.reset();
 	}
diff --git a/indra/newview/llvoavatarself.cpp b/indra/newview/llvoavatarself.cpp
index dec2e7efdf..739c021311 100644
--- a/indra/newview/llvoavatarself.cpp
+++ b/indra/newview/llvoavatarself.cpp
@@ -103,15 +103,7 @@ struct LocalTextureData
 //-----------------------------------------------------------------------------
 // Callback data
 //-----------------------------------------------------------------------------
-struct LLAvatarTexData
-{
-	LLAvatarTexData(const LLUUID& id, ETextureIndex index) : 
-		mAvatarID(id), 
-		mIndex(index) 
-	{}
-	LLUUID			mAvatarID;
-	ETextureIndex	mIndex;
-};
+
 
 /**
  **
@@ -156,6 +148,23 @@ void LLVOAvatarSelf::initInstance()
 	// adds attachment points to mScreen among other things
 	LLVOAvatar::initInstance();
 
+	llinfos << "Self avatar object created. Starting timer." << llendl;
+	mSelfLoadTimer.reset();
+	// clear all times to -1 for debugging
+	for (U32 i =0; i < LLVOAvatarDefines::TEX_NUM_INDICES; ++i)
+	{
+		for (U32 j = 0; j <= MAX_DISCARD_LEVEL; ++j)
+		{
+			mTextureLoadTimes[i][j] = -1.0f;
+		}
+	}
+
+	for (U32 i =0; i < LLVOAvatarDefines::BAKED_NUM_INDICES; ++i)
+	{
+		mBakedTextureTimes[i][0] = -1.0f;
+		mBakedTextureTimes[i][1] = -1.0f;
+	}
+
 	status &= buildMenus();
 	if (!status)
 	{
@@ -1117,12 +1126,12 @@ U32 LLVOAvatarSelf::getNumWearables(LLVOAvatarDefines::ETextureIndex i) const
 // virtual
 void LLVOAvatarSelf::localTextureLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src_raw, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata)
 {	
-	//llinfos << "onLocalTextureLoaded: " << src_vi->getID() << llendl;
 
 	const LLUUID& src_id = src_vi->getID();
 	LLAvatarTexData *data = (LLAvatarTexData *)userdata;
 	ETextureIndex index = data->mIndex;
 	if (!isIndexLocalTexture(index)) return;
+
 	LLLocalTextureObject *local_tex_obj = getLocalTextureObject(index, 0);
 
 	// fix for EXT-268. Preventing using of NULL pointer
@@ -1748,6 +1757,32 @@ BOOL LLVOAvatarSelf::getIsCloud()
 	return FALSE;
 }
 
+/*static*/
+void LLVOAvatarSelf::onTimingLocalTexLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata)
+{
+	gAgentAvatarp->timingLocalTexLoaded(success, src_vi, src, aux_src, discard_level, final, userdata);
+}
+
+void LLVOAvatarSelf::timingLocalTexLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata)
+{
+	LLAvatarTexData *data = (LLAvatarTexData *)userdata;
+	ETextureIndex index = data->mIndex;
+
+	if (discard_level >=0 && discard_level <= MAX_DISCARD_LEVEL) // ignore discard level -1, as it means we have no data.
+	{
+		mTextureLoadTimes[(U32)index][(U32)discard_level] = mSelfLoadTimer.getElapsedTimeF32();
+	}
+}
+
+void LLVOAvatarSelf::bakedTextureUpload(EBakedTextureIndex index, BOOL finished)
+{
+	U32 done = 0;
+	if (finished)
+	{
+		done = 1;
+	}
+	mBakedTextureTimes[index][done] = mSelfLoadTimer.getElapsedTimeF32();
+}
 
 const LLUUID& LLVOAvatarSelf::grabLocalTexture(ETextureIndex type, U32 index) const
 {
@@ -1907,6 +1942,7 @@ void LLVOAvatarSelf::setNewBakedTexture( ETextureIndex te, const LLUUID& uuid )
 	const LLVOAvatarDictionary::TextureEntry *texture_dict = LLVOAvatarDictionary::getInstance()->getTexture(te);
 	if (texture_dict->mIsBakedTexture)
 	{
+		bakedTextureUpload(texture_dict->mBakedTextureIndex, TRUE); // FALSE for start of upload, TRUE for finish.
 		llinfos << "New baked texture: " << texture_dict->mName << " UUID: " << uuid <<llendl;
 	}
 	else
@@ -1919,6 +1955,20 @@ void LLVOAvatarSelf::setNewBakedTexture( ETextureIndex te, const LLUUID& uuid )
 	if (!hasPendingBakedUploads())
 	{
 		gAgent.sendAgentSetAppearance();
+		F32 final_time = mSelfLoadTimer.getElapsedTimeF32();
+		llinfos << "time from avatar creation to load wearables: " << mTimeWearablesLoaded << llendl;
+		llinfos << "time from avatar creation to de-cloud: " << mTimeAvatarVisible << llendl;
+		llinfos << "time from avatar creation to de-cloud for others: " << final_time << llendl;
+		llinfos << "load time for each texture: " << llendl;
+		for (U32 i = 0; i < LLVOAvatarDefines::TEX_NUM_INDICES; ++i)
+		{
+			llinfos << "(" << i << "): " << (S32)mTextureLoadTimes[i][0] << "\t" << (S32)mTextureLoadTimes[i][1] << "\t" << (S32)mTextureLoadTimes[i][2] << "\t" << (S32)mTextureLoadTimes[i][3] << "\t" << (S32)mTextureLoadTimes[i][4] << "\t" << (S32)mTextureLoadTimes[i][5] << llendl;
+		}
+		llinfos << "Time points for each upload (start / finish)" << llendl;
+		for (U32 i = 0; i < LLVOAvatarDefines::BAKED_NUM_INDICES; ++i)
+		{
+			llinfos << "(" << i << "): " << (S32)mBakedTextureTimes[i][0] << " / " << (S32)mBakedTextureTimes[i][1] << llendl;
+		}
 	}
 }
 
diff --git a/indra/newview/llvoavatarself.h b/indra/newview/llvoavatarself.h
index 460291a929..03856b3a3b 100644
--- a/indra/newview/llvoavatarself.h
+++ b/indra/newview/llvoavatarself.h
@@ -124,6 +124,11 @@ public:
 	//--------------------------------------------------------------------
 public:
 	/*virtual*/ BOOL    getIsCloud();
+	void bakedTextureUpload(LLVOAvatarDefines::EBakedTextureIndex index, BOOL finished);
+	static void		onTimingLocalTexLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata);
+	void wearablesLoaded() { mTimeWearablesLoaded = mSelfLoadTimer.getElapsedTimeF32(); }
+	void avatarVisible() { mTimeAvatarVisible = mSelfLoadTimer.getElapsedTimeF32(); }
+
 private:
 
 	//--------------------------------------------------------------------
@@ -132,6 +137,14 @@ private:
 	U64				mLastRegionHandle;
 	LLFrameTimer	mRegionCrossingTimer;
 	S32				mRegionCrossingCount;
+	LLFrameTimer    mSelfLoadTimer;
+	F32				mTimeWearablesLoaded;
+	F32 			mTimeAvatarVisible;
+	F32 			mTextureLoadTimes[LLVOAvatarDefines::TEX_NUM_INDICES][MAX_DISCARD_LEVEL+1]; // stores load time for each texture,
+																		  // at each discard level
+	F32 			mBakedTextureTimes[LLVOAvatarDefines::BAKED_NUM_INDICES][2]; // stores time to start upload and finish upload of each baked texture
+
+	void		timingLocalTexLoaded(BOOL success, LLViewerFetchedTexture *src_vi, LLImageRaw* src, LLImageRaw* aux_src, S32 discard_level, BOOL final, void* userdata);
 	
 /**                    State
  **                                                                            **
@@ -332,6 +345,16 @@ public:
  **                                                                            **
  *******************************************************************************/
 
+struct LLAvatarTexData
+{
+	LLAvatarTexData(const LLUUID& id, LLVOAvatarDefines::ETextureIndex index) : 
+		mAvatarID(id), 
+		mIndex(index) 
+	{}
+	LLUUID			mAvatarID;
+	LLVOAvatarDefines::ETextureIndex	mIndex;
+};
+
 };
 
 extern LLVOAvatarSelf *gAgentAvatarp;
diff --git a/indra/newview/llwearable.cpp b/indra/newview/llwearable.cpp
index 3ecd1296bd..28613c8bcf 100644
--- a/indra/newview/llwearable.cpp
+++ b/indra/newview/llwearable.cpp
@@ -442,6 +442,9 @@ BOOL LLWearable::importFile( LLFILE* file )
 			delete mSavedTEMap[te];
 		}
 
+		image->setLoadedCallback(LLVOAvatarSelf::onTimingLocalTexLoaded,0,TRUE,FALSE, new LLVOAvatarSelf::LLAvatarTexData(id, (LLVOAvatarDefines::ETextureIndex)te));
+
+
 		LLUUID textureid(text_buffer);
 		mTEMap[te] = new LLLocalTextureObject(image, textureid);
 		mSavedTEMap[te] = new LLLocalTextureObject(image, textureid);