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

meow-7.2.2
Graham Linden graham@lindenlab.com 2018-04-11 20:14:33 +01:00
parent 6de246cd00
commit c0e16b2800
4 changed files with 97 additions and 36 deletions

View File

@ -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)

View File

@ -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;

View File

@ -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;
}

View File

@ -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();