Add stats for tex cache read / decode / fetch latency for comparison of old cache code with TCO.

4 files changed, 97 insertions, 36 deletions

diff --git a/indra/newview/lltexturefetch.cpp b/indra/newview/lltexturefetch.cpp
index 1f7796e6d0..3a515dd611 100644
--- a/indra/newview/lltexturefetch.cpp
+++ b/indra/newview/lltexturefetch.cpp
@@ -60,13 +60,16 @@
 #include "bufferarray.h"
 #include "bufferstream.h"
 #include "llcorehttputil.h"
-
 #include "llhttpretrypolicy.h"
 
 bool LLTextureFetchDebugger::sDebuggerEnabled = false ;
-LLTrace::EventStatHandle<LLUnit<F32, LLUnits::Percent> > LLTextureFetch::sCacheHitRate("texture_cache_hits");
-LLTrace::EventStatHandle<F64Milliseconds > LLTextureFetch::sCacheReadLatency("texture_cache_read_latency");
 
+LLTrace::CountStatHandle<F64> LLTextureFetch::sCacheHit("texture_cache_hit");
+LLTrace::CountStatHandle<F64> LLTextureFetch::sCacheAttempt("texture_cache_attempt");
+
+LLTrace::SampleStatHandle<F32Seconds> LLTextureFetch::sCacheReadLatency("texture_cache_read_latency");
+LLTrace::SampleStatHandle<F32Seconds> LLTextureFetch::sTexDecodeLatency("texture_decode_latency");
+LLTrace::SampleStatHandle<F32Seconds> LLTextureFetch::sTexFetchLatency("texture_fetch_latency");
 
 //////////////////////////////////////////////////////////////////////////////
 //
@@ -564,15 +567,21 @@ private:
 	F32 mImagePriority;
 	U32 mWorkPriority;
 	F32 mRequestedPriority;
-	S32                         mDesiredDiscard,
-								mSimRequestedDiscard,
-								mRequestedDiscard,
-								mLoadedDiscard,
-								mDecodedDiscard;
-	LLFrameTimer                mRequestedTimer,
-								mFetchTimer;
-	LLTimer			mCacheReadTimer;
-	F32				mCacheReadTime;
+	S32 mDesiredDiscard;
+	S32 mSimRequestedDiscard;
+	S32 mRequestedDiscard;
+    S32 mLoadedDiscard;
+    S32 mDecodedDiscard;
+	S32 mFullWidth;
+	S32 mFullHeight;
+	LLFrameTimer mRequestedDeltaTimer;
+	LLFrameTimer mFetchDeltaTimer;
+	LLTimer mCacheReadTimer;
+    LLTimer mDecodeTimer;
+    LLTimer mFetchTimer;
+	F32 mCacheReadTime; // time for cache read only
+    F32 mDecodeTime;    // time for decode only
+    F32 mFetchTime;     // total time from req to finished fetch
 	LLTextureCache::handle_t    mCacheReadHandle,
 								mCacheWriteHandle;
 	S32                         mRequestedSize,
@@ -906,6 +915,8 @@ LLTextureFetchWorker::LLTextureFetchWorker(LLTextureFetch* fetcher,
 	  mLoadedDiscard(-1),
 	  mDecodedDiscard(-1),
 	  mCacheReadTime(0.f),
+	  mDecodeTime(0.f),
+      mFetchTime(0.f),
 	  mCacheReadHandle(LLTextureCache::nullHandle()),
 	  mCacheWriteHandle(LLTextureCache::nullHandle()),
 	  mRequestedSize(0),
@@ -1167,7 +1178,7 @@ bool LLTextureFetchWorker::doWork(S32 param)
 
 	if (mState != DONE)
 	{
-		mFetchTimer.reset();
+		mFetchDeltaTimer.reset();
 	}
 
 	if (mState == INIT)
@@ -1218,7 +1229,9 @@ bool LLTextureFetchWorker::doWork(S32 param)
 			}
 			mFileSize = 0;
 			mLoaded = FALSE;			
-			
+
+            add(LLTextureFetch::sCacheAttempt, 1.0);
+
 			if (mUrl.compare(0, 7, "file://") == 0)
 			{
 				setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); // Set priority first since Responder may change it
@@ -1229,7 +1242,7 @@ bool LLTextureFetchWorker::doWork(S32 param)
 				CacheReadResponder* responder = new CacheReadResponder(mFetcher, mID, mFormattedImage);
 				mCacheReadHandle = mFetcher->mTextureCache->readFromCache(filename, mID, cache_priority,
 																		  offset, size, responder);
-				mCacheReadTimer.reset();
+                mCacheReadTimer.reset();                
 			}
 			else if ((mUrl.empty() || mFTType==FTT_SERVER_BAKE) && mFetcher->canLoadFromCache())
 			{
@@ -1260,6 +1273,7 @@ bool LLTextureFetchWorker::doWork(S32 param)
 			{
 				mCacheReadHandle = LLTextureCache::nullHandle();
 				setState(CACHE_POST);
+                add(LLTextureFetch::sCacheHit, 1.0);
 				// fall through
 			}
 			else
@@ -1297,7 +1311,6 @@ bool LLTextureFetchWorker::doWork(S32 param)
 			LL_DEBUGS(LOG_TXT) << mID << ": Cached. Bytes: " << mFormattedImage->getDataSize()
 							   << " Size: " << llformat("%dx%d",mFormattedImage->getWidth(),mFormattedImage->getHeight())
 							   << " Desired Discard: " << mDesiredDiscard << " Desired Size: " << mDesiredSize << LL_ENDL;
-			record(LLTextureFetch::sCacheHitRate, LLUnits::Ratio::fromValue(1));
 		}
 		else
 		{
@@ -1315,7 +1328,6 @@ bool LLTextureFetchWorker::doWork(S32 param)
 			}
 			
 			// fall through
-			record(LLTextureFetch::sCacheHitRate, LLUnits::Ratio::fromValue(0));
 		}
 	}
 
@@ -1571,7 +1583,7 @@ bool LLTextureFetchWorker::doWork(S32 param)
 			return true; // failed
 		}
 		
-		mRequestedTimer.reset();
+		mRequestedDeltaTimer.reset();
 		mLoaded = FALSE;
 		mGetStatus = LLCore::HttpStatus();
 		mGetReason.clear();
@@ -1898,6 +1910,8 @@ bool LLTextureFetchWorker::doWork(S32 param)
 				mFetcher->getFetchDebugger()->addHistoryEntry(this);
 			}
 
+            mDecodeTime = mDecodeTimer.getElapsedTimeF32();
+
 			if (mDecodedDiscard < 0)
 			{
 				if (mCachedSize > 0 && !mInLocalCache && mRetryAttempt == 0)
@@ -2002,6 +2016,7 @@ bool LLTextureFetchWorker::doWork(S32 param)
 		else
 		{
 			setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority);
+            mFetchTime = mFetchTimer.getElapsedTimeF32();
 			return true;
 		}
 	}
@@ -2945,11 +2960,12 @@ bool LLTextureFetch::getRequestFinished(const LLUUID& id, S32& discard_level,
 			discard_level = worker->mDecodedDiscard;
 			raw = worker->mRawImage;
 			aux = worker->mAuxImage;
-			F32Seconds cache_read_time(worker->mCacheReadTime);
-			if (cache_read_time != (F32Seconds)0.f)
-			{
-				record(sCacheReadLatency, cache_read_time);
-			}
+			sample(sTexDecodeLatency, worker->mDecodeTime);
+            sample(sTexFetchLatency, worker->mFetchTime);
+            sample(sCacheReadLatency, worker->mCacheReadTime);
+            worker->mCacheReadTimer.reset();
+            worker->mDecodeTimer.reset();
+            worker->mFetchTimer.reset();
 			res = true;
 			LL_DEBUGS(LOG_TXT) << id << ": Request Finished. State: " << worker->mState << " Discard: " << discard_level << LL_ENDL;
 			worker->unlockWorkMutex();									// -Mw
@@ -3253,7 +3269,7 @@ void LLTextureFetch::sendRequestListToSimulators()
 // 			req->setPriority(LLWorkerThread::PRIORITY_HIGH | req->mWorkPriority);
 				continue;
 			}
-			F32 elapsed = req->mRequestedTimer.getElapsedTimeF32();
+			F32 elapsed = req->mRequestedDeltaTimer.getElapsedTimeF32();
 			{
 				F32 delta_priority = llabs(req->mRequestedPriority - req->mImagePriority);
 				if ((req->mSimRequestedDiscard != req->mDesiredDiscard) ||
@@ -3322,7 +3338,7 @@ void LLTextureFetch::sendRequestListToSimulators()
 				req->mSentRequest = LLTextureFetchWorker::SENT_SIM;
 				req->mSimRequestedDiscard = req->mDesiredDiscard;
 				req->mRequestedPriority = req->mImagePriority;
-				req->mRequestedTimer.reset();
+				req->mRequestedDeltaTimer.reset();
 				req->unlockWorkMutex();									// -Mw
 				sim_request_count++;
 				if (sim_request_count >= IMAGES_PER_REQUEST)
@@ -3397,7 +3413,7 @@ void LLTextureFetch::sendRequestListToSimulators()
 // Locks:  Mw
 bool LLTextureFetchWorker::insertPacket(S32 index, U8* data, S32 size)
 {
-	mRequestedTimer.reset();
+	mRequestedDeltaTimer.reset();
 	if (index >= mTotalPackets)
 	{
 // 		LL_WARNS(LOG_TXT) << "Received Image Packet " << index << " > max: " << mTotalPackets << " for image: " << mID << LL_ENDL;
@@ -3606,8 +3622,8 @@ S32 LLTextureFetch::getFetchState(const LLUUID& id, F32& data_progress_p, F32& r
 	{
 		worker->lockWorkMutex();										// +Mw
 		state = worker->mState;
-		fetch_dtime = worker->mFetchTimer.getElapsedTimeF32();
-		request_dtime = worker->mRequestedTimer.getElapsedTimeF32();
+		fetch_dtime = worker->mFetchDeltaTimer.getElapsedTimeF32();
+		request_dtime = worker->mRequestedDeltaTimer.getElapsedTimeF32();
 		if (worker->mFileSize > 0)
 		{
 			if (state == LLTextureFetchWorker::LOAD_FROM_SIMULATOR)
diff --git a/indra/newview/lltexturefetch.h b/indra/newview/lltexturefetch.h
index cfa312ccd9..a2155bde1f 100644
--- a/indra/newview/lltexturefetch.h
+++ b/indra/newview/lltexturefetch.h
@@ -308,13 +308,16 @@ public:
 	S32 mPacketCount;
 	S32 mBadPacketCount;
 	
+    static LLTrace::CountStatHandle<F64>        sCacheHit;
+    static LLTrace::CountStatHandle<F64>        sCacheAttempt;
+    static LLTrace::SampleStatHandle<F32Seconds> sCacheReadLatency;
+    static LLTrace::SampleStatHandle<F32Seconds> sTexDecodeLatency;
+    static LLTrace::SampleStatHandle<F32Seconds> sTexFetchLatency;
+
 private:
 	LLMutex mQueueMutex;        //to protect mRequestMap and mCommands only
 	LLMutex mNetworkQueueMutex; //to protect mNetworkQueue, mHTTPTextureQueue and mCancelQueue.
 
-	static LLTrace::EventStatHandle<LLUnit<F32, LLUnits::Percent> > sCacheHitRate;
-	static LLTrace::EventStatHandle<F64Milliseconds > sCacheReadLatency;
-
 	LLTextureCache* mTextureCache;
 	LLImageDecodeThread* mImageDecodeThread;
 	
diff --git a/indra/newview/lltextureview.cpp b/indra/newview/lltextureview.cpp
index b7786bcdd7..95ecef6be8 100644
--- a/indra/newview/lltextureview.cpp
+++ b/indra/newview/lltextureview.cpp
@@ -240,9 +240,9 @@ void LLTextureBar::draw()
 		{ "REQ", LLColor4::yellow },// SEND_HTTP_REQ
 		{ "HTP", LLColor4::green },	// WAIT_HTTP_REQ
 		{ "DEC", LLColor4::yellow },// DECODE_IMAGE
-		{ "DEC", LLColor4::green }, // DECODE_IMAGE_UPDATE
+		{ "DEU", LLColor4::green }, // DECODE_IMAGE_UPDATE
 		{ "WRT", LLColor4::purple },// WRITE_TO_CACHE
-		{ "WRT", LLColor4::orange },// WAIT_ON_WRITE
+		{ "WWT", LLColor4::orange },// WAIT_ON_WRITE
 		{ "END", LLColor4::red },   // DONE
 #define LAST_STATE 14
 		{ "CRE", LLColor4::magenta }, // LAST_STATE+1
@@ -530,6 +530,25 @@ void LLGLTexMemBar::draw()
 	LLFontGL::getFontMonospace()->renderUTF8(text, 0, 0, v_offset + line_height*6,
 											 text_color, LLFontGL::LEFT, LLFontGL::TOP);
 
+    LLTrace::Recording& recording = LLViewerStats::instance().getRecording();
+
+    F64 cacheHits     = recording.getSampleCount(LLTextureFetch::sCacheHit);
+    F64 cacheAttempts = recording.getSampleCount(LLTextureFetch::sCacheAttempt);
+
+	F32 cacheHitRate = (cacheAttempts > 0.0) ? F32((cacheHits / cacheAttempts) * 100.0f) : 0.0f;
+
+    U32 cacheReadLatMin = U32(recording.getMin(LLTextureFetch::sCacheReadLatency).value() * 1000.0f);
+    U32 cacheReadLatMed = U32(recording.getMean(LLTextureFetch::sCacheReadLatency).value() * 1000.0f);
+    U32 cacheReadLatMax = U32(recording.getMax(LLTextureFetch::sCacheReadLatency).value() * 1000.0f);
+
+    U32 texDecodeLatMin = U32(recording.getMin(LLTextureFetch::sTexDecodeLatency).value() * 1000.0f);
+    U32 texDecodeLatMed = U32(recording.getMean(LLTextureFetch::sTexDecodeLatency).value() * 1000.0f);
+    U32 texDecodeLatMax = U32(recording.getMax(LLTextureFetch::sTexDecodeLatency).value() * 1000.0f);
+
+    U32 texFetchLatMin = U32(recording.getMin(LLTextureFetch::sTexFetchLatency).value() * 1000.0f);
+    U32 texFetchLatMed = U32(recording.getMean(LLTextureFetch::sTexFetchLatency).value() * 1000.0f);
+    U32 texFetchLatMax = U32(recording.getMax(LLTextureFetch::sTexFetchLatency).value() * 1000.0f);
+
 	text = llformat("GL Tot: %d/%d MB Bound: %d/%d MB FBO: %d MB Raw Tot: %d MB Bias: %.2f Cache: %.1f/%.1f MB",
 					total_mem.value(),
 					max_total_mem.value(),
@@ -542,7 +561,7 @@ void LLGLTexMemBar::draw()
 					cache_max_usage);
 	//, cache_entries, cache_max_entries
 
-	LLFontGL::getFontMonospace()->renderUTF8(text, 0, 0, v_offset + line_height*5,
+	LLFontGL::getFontMonospace()->renderUTF8(text, 0, 0, v_offset + line_height*6,
 											 text_color, LLFontGL::LEFT, LLFontGL::TOP);
 
 	U32 cache_read(0U), cache_write(0U), res_wait(0U);
@@ -558,6 +577,21 @@ void LLGLTexMemBar::draw()
 					cache_write,
 					res_wait);
 
+	LLFontGL::getFontMonospace()->renderUTF8(text, 0, 0, v_offset + line_height*5,
+											 text_color, LLFontGL::LEFT, LLFontGL::TOP);
+
+    text = llformat("CacheHitRate: %3.2f Read: %d/%d/%d Decode: %d/%d/%d Fetch: %d/%d/%d",
+                    cacheHitRate,
+                    cacheReadLatMin,
+                    cacheReadLatMed,
+                    cacheReadLatMax,
+                    texDecodeLatMin,
+                    texDecodeLatMed,
+                    texDecodeLatMax,
+                    texFetchLatMin,
+                    texFetchLatMed,
+                    texFetchLatMax);
+
 	LLFontGL::getFontMonospace()->renderUTF8(text, 0, 0, v_offset + line_height*4,
 											 text_color, LLFontGL::LEFT, LLFontGL::TOP);
 
@@ -640,7 +674,7 @@ BOOL LLGLTexMemBar::handleMouseDown(S32 x, S32 y, MASK mask)
 LLRect LLGLTexMemBar::getRequiredRect()
 {
 	LLRect rect;
-	rect.mTop = 68; //LLFontGL::getFontMonospace()->getLineHeight() * 6;
+	rect.mTop = 78; //LLFontGL::getFontMonospace()->getLineHeight() * 6;
 	return rect;
 }
 
@@ -736,7 +770,7 @@ LLTextureView::~LLTextureView()
 typedef std::pair<F32,LLViewerFetchedTexture*> decode_pair_t;
 struct compare_decode_pair
 {
-	bool operator()(const decode_pair_t& a, const decode_pair_t& b)
+	bool operator()(const decode_pair_t& a, const decode_pair_t& b) const
 	{
 		return a.first > b.first;
 	}
diff --git a/indra/newview/llviewertexture.cpp b/indra/newview/llviewertexture.cpp
index e5a1bed48c..6e5193f6a3 100644
--- a/indra/newview/llviewertexture.cpp
+++ b/indra/newview/llviewertexture.cpp
@@ -1178,9 +1178,17 @@ void LLViewerFetchedTexture::loadFromFastCache()
 	}
 	mInFastCacheList = FALSE;
 
+    add(LLTextureFetch::sCacheAttempt, 1.0);
+
+    LLTimer fastCacheTimer;
 	mRawImage = LLAppViewer::getTextureCache()->readFromFastCache(getID(), mRawDiscardLevel);
 	if(mRawImage.notNull())
 	{
+        F32 cachReadTime = fastCacheTimer.getElapsedTimeF32();
+
+        add(LLTextureFetch::sCacheHit, 1.0);
+        sample(LLTextureFetch::sCacheReadLatency, cachReadTime);
+
 		mFullWidth = mRawImage->getWidth() << mRawDiscardLevel;
 		mFullHeight = mRawImage->getHeight() << mRawDiscardLevel;
 		setTexelsPerImage();