diff --git a/indra/llcommon/llstatenums.h b/indra/llcommon/llstatenums.h index 608ac5473..81c4085d1 100644 --- a/indra/llcommon/llstatenums.h +++ b/indra/llcommon/llstatenums.h @@ -63,6 +63,13 @@ enum LL_SIM_STAT_SIMSPARETIME = 32, LL_SIM_STAT_SIMSLEEPTIME = 33, LL_SIM_STAT_IOPUMPTIME = 34, + LL_SIM_STAT_PCTSCRIPTSRUN = 35, + LL_SIM_STAT_REGION_IDLE = 36, // dataserver only + LL_SIM_STAT_REGION_IDLE_POSSIBLE = 37, // dataserver only + LL_SIM_STAT_SIMAISTEPTIMEMS = 38, + LL_SIM_STAT_SKIPPEDAISILSTEPS_PS = 39, + LL_SIM_STAT_PCTSTEPPEDCHARACTERS = 40 + }; #endif diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index 76ba4b9cb..dd7255e21 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -690,9 +690,6 @@ bool LLAppViewer::init() ////////////////////////////////////////////////////////////////////////////// // *FIX: The following code isn't grouped into functions yet. - // Statistics / debug timer initialization - init_statistics(); - // // Various introspection concerning the libs we're using - particularly // the libs involved in getting to a full login screen. @@ -3969,7 +3966,7 @@ void LLAppViewer::idle() idle_afk_check(); // Update statistics for this frame - update_statistics(gFrameCount); + update_statistics(); } //////////////////////////////////////// diff --git a/indra/newview/llfloaterstats.cpp b/indra/newview/llfloaterstats.cpp index fb9b1cc24..a60619882 100644 --- a/indra/newview/llfloaterstats.cpp +++ b/indra/newview/llfloaterstats.cpp @@ -45,6 +45,7 @@ #include "pipeline.h" #include "llviewerobjectlist.h" #include "llviewertexturelist.h" +#include "lltexturefetch.h" #include "sgmemstat.h" const S32 LL_SCROLL_BORDER = 1; @@ -151,10 +152,36 @@ void LLFloaterStats::buildStats() stat_barp->mLabelSpacing = 500.f; stat_barp->mPerSec = TRUE; + stat_barp = render_statviewp->addStat("Object Cache Hit Rate", &(LLViewerStats::getInstance()->mNumNewObjectsStat), std::string(), false, true); + stat_barp->setLabel("Object Cache Hit Rate"); + stat_barp->setUnitLabel("%"); + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 100.f; + stat_barp->mTickSpacing = 20.f; + stat_barp->mLabelSpacing = 20.f; + stat_barp->mPerSec = FALSE; // Texture statistics LLStatView *texture_statviewp = render_statviewp->addStatView("texture stat view", "Texture", "OpenDebugStatTexture", rect); + stat_barp = texture_statviewp->addStat("Cache Hit Rate", &(LLTextureFetch::sCacheHitRate), std::string(), false, true); + stat_barp->setLabel("Cache Hit Rate"); + stat_barp->setUnitLabel("%"); + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 100.f; + stat_barp->mTickSpacing = 20.f; + stat_barp->mLabelSpacing = 20.f; + stat_barp->mPerSec = FALSE; + + stat_barp = texture_statviewp->addStat("Cache Read Latency", &(LLTextureFetch::sCacheReadLatency), std::string(), false, true); + stat_barp->setUnitLabel("msec"); + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 1000.f; + stat_barp->mTickSpacing = 100.f; + stat_barp->mLabelSpacing = 200.f; + stat_barp->mPerSec = FALSE; + stat_barp->mDisplayMean = FALSE; + stat_barp = texture_statviewp->addStat("Count", &(LLViewerStats::getInstance()->mNumImagesStat), "DebugStatModeTextureCount"); stat_barp->setUnitLabel(""); stat_barp->mMinBar = 0.f; @@ -365,6 +392,15 @@ void LLFloaterStats::buildStats() stat_barp->mPerSec = FALSE; stat_barp->mDisplayMean = FALSE; + stat_barp = sim_statviewp->addStat("Scripts Run", &(LLViewerStats::getInstance()->mSimPctScriptsRun), std::string(), false, true); + stat_barp->setUnitLabel("%"); + stat_barp->mPrecision = 3; + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 100.f; + stat_barp->mTickSpacing = 10.f; + stat_barp->mLabelSpacing = 20.f; + stat_barp->mPerSec = FALSE; + stat_barp = sim_statviewp->addStat("Script Events", &(LLViewerStats::getInstance()->mSimScriptEPS), "DebugStatModeSimScriptEvents"); stat_barp->setUnitLabel(" eps"); stat_barp->mPrecision = 0; @@ -375,6 +411,35 @@ void LLFloaterStats::buildStats() stat_barp->mPerSec = FALSE; stat_barp->mDisplayMean = FALSE; + LLStatView *pathfinding_viewp = sim_statviewp->addStatView("pathfinding view", "Pathfinding Details", std::string(), rect); + stat_barp = pathfinding_viewp->addStat("AI Step Time", &(LLViewerStats::getInstance()->mSimSimAIStepMsec)); + stat_barp->setUnitLabel("ms"); + stat_barp->mPrecision = 3; + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 40.f; + stat_barp->mTickSpacing = 10.f; + stat_barp->mLabelSpacing = 20.f; + stat_barp->mPerSec = FALSE; + stat_barp->mDisplayMean = FALSE; + + stat_barp = render_statviewp->addStat("Skipped Silhouette Steps", &(LLViewerStats::getInstance()->mSimSimSkippedSilhouetteSteps)); + stat_barp->setUnitLabel("/sec"); + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 45.f; + stat_barp->mTickSpacing = 4.f; + stat_barp->mLabelSpacing = 8.f; + stat_barp->mPrecision = 0; + + stat_barp = pathfinding_viewp->addStat("Characters Updated", &(LLViewerStats::getInstance()->mSimSimPctSteppedCharacters)); + stat_barp->setUnitLabel("%"); + stat_barp->mPrecision = 1; + stat_barp->mMinBar = 0.f; + stat_barp->mMaxBar = 100.f; + stat_barp->mTickSpacing = 10.f; + stat_barp->mLabelSpacing = 20.f; + stat_barp->mPerSec = FALSE; + stat_barp->mDisplayMean = TRUE; + stat_barp = sim_statviewp->addStat("Packets In", &(LLViewerStats::getInstance()->mSimInPPS), "DebugStatModeSimInPPS"); stat_barp->setUnitLabel(" pps"); stat_barp->mPrecision = 0; diff --git a/indra/newview/lltexturefetch.cpp b/indra/newview/lltexturefetch.cpp index 276bc4a0a..accd96b42 100644 --- a/indra/newview/lltexturefetch.cpp +++ b/indra/newview/lltexturefetch.cpp @@ -53,6 +53,7 @@ #include "llviewertexture.h" #include "llviewerregion.h" #include "llviewerstats.h" +#include "llviewerstatsrecorder.h" #include "llworld.h" #include "llstartup.h" #include "llbuffer.h" @@ -61,6 +62,9 @@ class AIHTTPTimeoutPolicy; extern AIHTTPTimeoutPolicy HTTPGetResponder_timeout; extern AIHTTPTimeoutPolicy lcl_responder_timeout; +LLStat LLTextureFetch::sCacheHitRate("texture_cache_hits", 128); +LLStat LLTextureFetch::sCacheReadLatency("texture_cache_read_latency", 128); + ////////////////////////////////////////////////////////////////////////////// class LLTextureFetchWorker : public LLWorkerClass { @@ -250,6 +254,8 @@ private: S32 mDecodedDiscard; LLFrameTimer mRequestedTimer; LLFrameTimer mFetchTimer; + LLTimer mCacheReadTimer; + F32 mCacheReadTime; LLTextureCache::handle_t mCacheReadHandle; LLTextureCache::handle_t mCacheWriteHandle; std::vector mHttpBuffer; @@ -289,9 +295,6 @@ private: S32 mLastPacket; U16 mTotalPackets; U8 mImageCodec; -#if HTTP_METRICS - LLViewerAssetStats::duration_t mMetricsStartTime; -#endif }; ////////////////////////////////////////////////////////////////////////////// @@ -384,20 +387,6 @@ public: } mFetcher->removeFromHTTPQueue(mID, data_size); - -#if HTTP_METRICS - if (worker->mMetricsStartTime) - { - LLViewerAssetStatsFF::record_response_thread1(LLViewerAssetType::AT_TEXTURE, - true, - LLImageBase::TYPE_AVATAR_BAKE == worker->mType, - LLViewerAssetStatsFF::get_timestamp() - worker->mMetricsStartTime); - worker->mMetricsStartTime = 0; - } - LLViewerAssetStatsFF::record_dequeue_thread1(LLViewerAssetType::AT_TEXTURE, - true, - LLImageBase::TYPE_AVATAR_BAKE == worker->mType); -#endif } else { @@ -514,230 +503,6 @@ static bool sgConnectionThrottle() { } #endif -#if HTTP_METRICS -// Cross-thread messaging for asset metrics. - -/** - * @brief Base class for cross-thread requests made of the fetcher - * - * I believe the intent of the LLQueuedThread class was to - * have these operations derived from LLQueuedThread::QueuedRequest - * but the texture fetcher has elected to manage the queue - * in its own manner. So these are free-standing objects which are - * managed in simple FIFO order on the mCommands queue of the - * LLTextureFetch object. - * - * What each represents is a simple command sent from an - * outside thread into the TextureFetch thread to be processed - * in order and in a timely fashion (though not an absolute - * higher priority than other operations of the thread). - * Each operation derives a new class from the base customizing - * members, constructors and the doWork() method to effect - * the command. - * - * The flow is one-directional. There are two global instances - * of the LLViewerAssetStats collector, one for the main program's - * thread pointed to by gViewerAssetStatsMain and one for the - * TextureFetch thread pointed to by gViewerAssetStatsThread1. - * Common operations has each thread recording metrics events - * into the respective collector unconcerned with locking and - * the state of any other thread. But when the agent moves into - * a different region or the metrics timer expires and a report - * needs to be sent back to the grid, messaging across threads - * is required to distribute data and perform global actions. - * In pseudo-UML, it looks like: - * - * Main Thread1 - * . . - * . . - * +-----+ . - * | AM | . - * +--+--+ . - * +-------+ | . - * | Main | +--+--+ . - * | | | SRE |---. . - * | Stats | +-----+ \ . - * | | | \ (uuid) +-----+ - * | Coll. | +--+--+ `-------->| SR | - * +-------+ | MSC | +--+--+ - * | ^ +-----+ | - * | | (uuid) / . +-----+ (uuid) - * | `--------' . | MSC |---------. - * | . +-----+ | - * | +-----+ . v - * | | TE | . +-------+ - * | +--+--+ . | Thd1 | - * | | . | | - * | +-----+ . | Stats | - * `--------->| RSC | . | | - * +--+--+ . | Coll. | - * | . +-------+ - * +--+--+ . | - * | SME |---. . | - * +-----+ \ . | - * . \ (clone) +-----+ | - * . `-------->| SM | | - * . +--+--+ | - * . | | - * . +-----+ | - * . | RSC |<--------' - * . +-----+ - * . | - * . +-----+ - * . | CP |--> HTTP POST - * . +-----+ - * . . - * . . - * - * - * Key: - * - * SRE - Set Region Enqueued. Enqueue a 'Set Region' command in - * the other thread providing the new UUID of the region. - * TFReqSetRegion carries the data. - * SR - Set Region. New region UUID is sent to the thread-local - * collector. - * SME - Send Metrics Enqueued. Enqueue a 'Send Metrics' command - * including an ownership transfer of a cloned LLViewerAssetStats. - * TFReqSendMetrics carries the data. - * SM - Send Metrics. Global metrics reporting operation. Takes - * the cloned stats from the command, merges it with the - * thread's local stats, converts to LLSD and sends it on - * to the grid. - * AM - Agent Moved. Agent has completed some sort of move to a - * new region. - * TE - Timer Expired. Metrics timer has expired (on the order - * of 10 minutes). - * CP - CURL Post - * MSC - Modify Stats Collector. State change in the thread-local - * collector. Typically a region change which affects the - * global pointers used to find the 'current stats'. - * RSC - Read Stats Collector. Extract collector data cloning it - * (i.e. deep copy) when necessary. - * - */ -class LLTextureFetch::TFRequest // : public LLQueuedThread::QueuedRequest -{ -public: - // Default ctors and assignment operator are correct. - - virtual ~TFRequest() - {} - - // Patterned after QueuedRequest's method but expected behavior - // is different. Always expected to complete on the first call - // and work dispatcher will assume the same and delete the - // request after invocation. - virtual bool doWork(LLTextureFetch * fetcher) = 0; -}; - -namespace -{ - -/** - * @brief Implements a 'Set Region' cross-thread command. - * - * When an agent moves to a new region, subsequent metrics need - * to be binned into a new or existing stats collection in 1:1 - * relationship with the region. We communicate this region - * change across the threads involved in the communication with - * this message. - * - * Corresponds to LLTextureFetch::commandSetRegion() - */ -class TFReqSetRegion : public LLTextureFetch::TFRequest -{ -public: - TFReqSetRegion(U64 region_handle) - : LLTextureFetch::TFRequest(), - mRegionHandle(region_handle) - {} - TFReqSetRegion & operator=(const TFReqSetRegion &); // Not defined - - virtual ~TFReqSetRegion() - {} - - virtual bool doWork(LLTextureFetch * fetcher); - -public: - const U64 mRegionHandle; -}; - - -/** - * @brief Implements a 'Send Metrics' cross-thread command. - * - * This is the big operation. The main thread gathers metrics - * for a period of minutes into LLViewerAssetStats and other - * objects then makes a snapshot of the data by cloning the - * collector. This command transfers the clone, along with a few - * additional arguments (UUIDs), handing ownership to the - * TextureFetch thread. It then merges its own data into the - * cloned copy, converts to LLSD and kicks off an HTTP POST of - * the resulting data to the currently active metrics collector. - * - * Corresponds to LLTextureFetch::commandSendMetrics() - */ - -class TFReqSendMetrics : public LLTextureFetch::TFRequest -{ -public: - /** - * Construct the 'Send Metrics' command to have the TextureFetch - * thread add and log metrics data. - * - * @param caps_url URL of a "ViewerMetrics" Caps target - * to receive the data. Does not have to - * be associated with a particular region. - * - * @param session_id UUID of the agent's session. - * - * @param agent_id UUID of the agent. (Being pure here...) - * - * @param main_stats Pointer to a clone of the main thread's - * LLViewerAssetStats data. Thread1 takes - * ownership of the copy and disposes of it - * when done. - */ - - TFReqSendMetrics(const std::string & caps_url, - const LLUUID & session_id, - const LLUUID & agent_id, - LLViewerAssetStats * main_stats) - : LLTextureFetch::TFRequest(), - mCapsURL(caps_url), - mSessionID(session_id), - mAgentID(agent_id), - mMainStats(main_stats) - {} - TFReqSendMetrics & operator=(const TFReqSendMetrics &); // Not defined - - virtual ~TFReqSendMetrics(); - - virtual bool doWork(LLTextureFetch * fetcher); - -public: - const std::string mCapsURL; - const LLUUID mSessionID; - const LLUUID mAgentID; - LLViewerAssetStats * mMainStats; -}; - -/* - * Examines the merged viewer metrics report and if found to be too long, - * will attempt to truncate it in some reasonable fashion. - * - * @param max_regions Limit of regions allowed in report. - * - * @param metrics Full, merged viewer metrics report. - * - * @returns If data was truncated, returns true. - */ -bool truncate_viewer_metrics(int max_regions, LLSD & metrics); - -} // end of anonymous namespace -#endif - ////////////////////////////////////////////////////////////////////////////// //static @@ -757,11 +522,6 @@ const char* LLTextureFetchWorker::sStateDescs[] = { "DONE", }; -#if HTTP_METRICS -// static -volatile bool LLTextureFetch::svMetricsDataBreak(true); // Start with a data break -#endif - // called from MAIN THREAD LLTextureFetchWorker::LLTextureFetchWorker(LLTextureFetch* fetcher, @@ -786,6 +546,7 @@ LLTextureFetchWorker::LLTextureFetchWorker(LLTextureFetch* fetcher, mRequestedDiscard(-1), mLoadedDiscard(-1), mDecodedDiscard(-1), + mCacheReadTime(0.f), mCacheReadHandle(LLTextureCache::nullHandle()), mCacheWriteHandle(LLTextureCache::nullHandle()), mRequestedSize(0), @@ -810,9 +571,6 @@ LLTextureFetchWorker::LLTextureFetchWorker(LLTextureFetch* fetcher, mLastPacket(-1), mTotalPackets(0), mImageCodec(IMG_CODEC_INVALID) -#if HTTP_METRICS - ,mMetricsStartTime(0) -#endif { mCanUseNET = mUrl.empty() ; @@ -1064,6 +822,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(); } else if (mUrl.empty()) { @@ -1072,8 +831,9 @@ bool LLTextureFetchWorker::doWork(S32 param) CacheReadResponder* responder = new CacheReadResponder(mFetcher, mID, mFormattedImage); mCacheReadHandle = mFetcher->mTextureCache->readFromCache(mID, cache_priority, offset, size, responder); + mCacheReadTimer.reset(); } - else if(mCanUseHTTP) + else if(!mUrl.empty() && mCanUseHTTP) { if (!(mUrl.compare(0, 7, "http://") == 0)) { @@ -1101,6 +861,9 @@ bool LLTextureFetchWorker::doWork(S32 param) } else { + // + //This should never happen + // return false; } } @@ -1124,7 +887,7 @@ bool LLTextureFetchWorker::doWork(S32 param) LL_DEBUGS("Texture") << mID << ": Cached. Bytes: " << mFormattedImage->getDataSize() << " Size: " << llformat("%dx%d",mFormattedImage->getWidth(),mFormattedImage->getHeight()) << " Desired Discard: " << mDesiredDiscard << " Desired Size: " << mDesiredSize << LL_ENDL; - // fall through + LLTextureFetch::sCacheHitRate.addValue(100.f); } else { @@ -1139,7 +902,9 @@ bool LLTextureFetchWorker::doWork(S32 param) LL_DEBUGS("Texture") << mID << ": Not in Cache" << LL_ENDL; mState = LOAD_FROM_NETWORK; } + // fall through + LLTextureFetch::sCacheHitRate.addValue(0.f); } } @@ -1198,15 +963,6 @@ bool LLTextureFetchWorker::doWork(S32 param) mRequestedDiscard = mDesiredDiscard; mSentRequest = QUEUED; mFetcher->addToNetworkQueue(this); -#if HTTP_METRICS - if (! mMetricsStartTime) - { - mMetricsStartTime = LLViewerAssetStatsFF::get_timestamp(); - } - LLViewerAssetStatsFF::record_enqueue_thread1(LLViewerAssetType::AT_TEXTURE, - false, - LLImageBase::TYPE_AVATAR_BAKE == mType); -#endif setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return false; @@ -1217,12 +973,6 @@ bool LLTextureFetchWorker::doWork(S32 param) //llassert_always(mFetcher->mNetworkQueue.find(mID) != mFetcher->mNetworkQueue.end()); // Make certain this is in the network queue //mFetcher->addToNetworkQueue(this); - //if (! mMetricsStartTime) - //{ - // mMetricsStartTime = LLViewerAssetStatsFF::get_timestamp(); - //} - //LLViewerAssetStatsFF::record_enqueue_thread1(LLViewerAssetType::AT_TEXTURE, false, - // LLImageBase::TYPE_AVATAR_BAKE == mType); //setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return false; } @@ -1247,33 +997,10 @@ bool LLTextureFetchWorker::doWork(S32 param) setPriority(LLWorkerThread::PRIORITY_HIGH | mWorkPriority); mState = DECODE_IMAGE; mWriteToCacheState = SHOULD_WRITE; - -#if HTTP_METRICS - if (mMetricsStartTime) - { - LLViewerAssetStatsFF::record_response_thread1(LLViewerAssetType::AT_TEXTURE, - false, - LLImageBase::TYPE_AVATAR_BAKE == mType, - LLViewerAssetStatsFF::get_timestamp() - mMetricsStartTime); - mMetricsStartTime = 0; - } - LLViewerAssetStatsFF::record_dequeue_thread1(LLViewerAssetType::AT_TEXTURE, - false, - LLImageBase::TYPE_AVATAR_BAKE == mType); -#endif } else { mFetcher->addToNetworkQueue(this); // failsafe -#if HTTP_METRICS - if (! mMetricsStartTime) - { - mMetricsStartTime = LLViewerAssetStatsFF::get_timestamp(); - } - LLViewerAssetStatsFF::record_enqueue_thread1(LLViewerAssetType::AT_TEXTURE, - false, - LLImageBase::TYPE_AVATAR_BAKE == mType); -#endif setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); } return false; @@ -1340,15 +1067,6 @@ bool LLTextureFetchWorker::doWork(S32 param) mState = WAIT_HTTP_REQ; mFetcher->addToHTTPQueue(mID); -#if HTTP_METRICS - if (! mMetricsStartTime) - { - mMetricsStartTime = LLViewerAssetStatsFF::get_timestamp(); - } - LLViewerAssetStatsFF::record_enqueue_thread1(LLViewerAssetType::AT_TEXTURE, - true, - LLImageBase::TYPE_AVATAR_BAKE == mType); -#endif if(mRequestedOffset>0) { @@ -1573,11 +1291,12 @@ bool LLTextureFetchWorker::doWork(S32 param) if (mState == DECODE_IMAGE) { static LLCachedControl textures_decode_disabled(gSavedSettings,"TextureDecodeDisabled"); - if(textures_decode_disabled) + + setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); // Set priority first since Responder may change it + if (textures_decode_disabled) { // for debug use, don't decode mState = DONE; - setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return true; } @@ -1585,7 +1304,6 @@ bool LLTextureFetchWorker::doWork(S32 param) { // We aborted, don't decode mState = DONE; - setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return true; } @@ -1595,7 +1313,6 @@ bool LLTextureFetchWorker::doWork(S32 param) //abort, don't decode mState = DONE; - setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return true; } if (mLoadedDiscard < 0) @@ -1604,10 +1321,9 @@ bool LLTextureFetchWorker::doWork(S32 param) //abort, don't decode mState = DONE; - setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); return true; } - setPriority(LLWorkerThread::PRIORITY_LOW | mWorkPriority); // Set priority first since Responder may change it + mRawImage = NULL; mAuxImage = NULL; llassert_always(mFormattedImage.notNull()); @@ -1899,6 +1615,7 @@ S32 LLTextureFetchWorker::callbackHttpGet(const LLChannelDescriptors& channels, LL_DEBUGS("Texture") << "HTTP RECEIVED: " << mID.asString() << " Bytes: " << data_size << LL_ENDL; if (data_size > 0) { + LLViewerStatsRecorder::instance().textureFetch(data_size); // *TODO: set the formatted image data here directly to avoid the copy llassert(mHttpBuffer.empty()); mHttpBuffer.resize(data_size); @@ -1932,6 +1649,7 @@ S32 LLTextureFetchWorker::callbackHttpGet(const LLChannelDescriptors& channels, mLoaded = TRUE; setPriority(LLWorkerThread::PRIORITY_HIGH | mWorkPriority); + LLViewerStatsRecorder::instance().log(0.2f); return data_size ; } @@ -2017,6 +1735,7 @@ void LLTextureFetchWorker::callbackDecoded(bool success, LLImageRaw* raw, LLImag mDecoded = TRUE; // llinfos << mID << " : DECODE COMPLETE " << llendl; setPriority(LLWorkerThread::PRIORITY_HIGH | mWorkPriority); + mCacheReadTime = mCacheReadTimer.getElapsedTimeF32(); } ////////////////////////////////////////////////////////////////////////////// @@ -2058,13 +1777,7 @@ LLTextureFetch::LLTextureFetch(LLTextureCache* cache, LLImageDecodeThread* image mTextureBandwidth(0), mHTTPTextureBits(0), mTotalHTTPRequests(0) -#if HTTP_METRICS - ,mQAMode(qa_mode) -#endif { -#if HTTP_METRICS - mCurlPOSTRequestCount = 0; -#endif mTextureInfo.setUpLogging(gSavedSettings.getBOOL("LogTextureDownloadsToViewerLog"), gSavedSettings.getBOOL("LogTextureDownloadsToSimulator"), gSavedSettings.getU32("TextureLoggingThreshold")); } @@ -2072,14 +1785,6 @@ LLTextureFetch::~LLTextureFetch() { clearDeleteList() ; -#if HTTP_METRICS - while (! mCommands.empty()) - { - TFRequest * req(mCommands.front()); - mCommands.erase(mCommands.begin()); - delete req; - } -#endif // ~LLQueuedThread() called here } @@ -2341,6 +2046,11 @@ bool LLTextureFetch::getRequestFinished(const LLUUID& id, S32& discard_level, discard_level = worker->mDecodedDiscard; raw = worker->mRawImage; aux = worker->mAuxImage; + F32 cache_read_time = worker->mCacheReadTime; + if (cache_read_time != 0.f) + { + sCacheReadLatency.addValue(cache_read_time * 1000.f); + } res = true; LL_DEBUGS("Texture") << id << ": Request Finished. State: " << worker->mState << " Discard: " << discard_level << LL_ENDL; worker->unlockWorkMutex(); @@ -2393,10 +2103,6 @@ S32 LLTextureFetch::getPending() LLMutexLock lock(&mQueueMutex); res = mRequestQueue.size(); -#if HTTP_METRICS - res += mCurlPOSTRequestCount; - res += mCommands.size(); -#endif } unlockData(); return res; @@ -2414,22 +2120,7 @@ bool LLTextureFetch::runCondition() // // Changes here may need to be reflected in getPending(). -#if HTTP_METRICS - bool have_no_commands(false); - { - LLMutexLock lock(&mQueueMutex); - - have_no_commands = mCommands.empty(); - } - - bool have_no_curl_requests(0 == mCurlPOSTRequestCount); - - return ! (have_no_commands - && have_no_curl_requests - && (mRequestQueue.empty() && mIdleThread)); // From base class -#else - return !(mRequestQueue.empty() && mIdleThread); -#endif + return ! (mRequestQueue.empty() && mIdleThread); // From base class } ////////////////////////////////////////////////////////////////////////////// @@ -2437,10 +2128,6 @@ bool LLTextureFetch::runCondition() // MAIN THREAD (unthreaded envs), WORKER THREAD (threaded envs) void LLTextureFetch::commonUpdate() { -#if HTTP_METRICS - // Run a cross-thread command, if any. - cmdDoWork(); -#endif } @@ -2799,11 +2486,16 @@ bool LLTextureFetch::receiveImageHeader(const LLHost& host, const LLUUID& id, U8 mNetworkQueueMutex.unlock() ; return false; } + + LLViewerStatsRecorder::instance().textureFetch(data_size); + LLViewerStatsRecorder::instance().log(0.1f); + worker->lockWorkMutex(); - // Copy header data into image object - worker->mImageCodec = codec; - worker->mTotalPackets = packets; + + // Copy header data into image object + worker->mImageCodec = codec; + worker->mTotalPackets = packets; worker->mFileSize = (S32)totalbytes; llassert_always(totalbytes > 0); llassert_always(data_size == FIRST_PACKET_SIZE || data_size == worker->mFileSize); @@ -2844,8 +2536,12 @@ bool LLTextureFetch::receiveImagePacket(const LLHost& host, const LLUUID& id, U1 mNetworkQueueMutex.unlock() ; return false; } + + LLViewerStatsRecorder::instance().textureFetch(data_size); + LLViewerStatsRecorder::instance().log(0.1f); worker->lockWorkMutex(); + res = worker->insertPacket(packet_num, data, data_size); @@ -2959,277 +2655,12 @@ void LLTextureFetch::dump() << " STATE: " << worker->sStateDescs[worker->mState] << llendl; } -} -////////////////////////////////////////////////////////////////////////////// - -// cross-thread command methods - -#if HTTP_METRICS -void LLTextureFetch::commandSetRegion(U64 region_handle) -{ - TFReqSetRegion * req = new TFReqSetRegion(region_handle); - - cmdEnqueue(req); -} - -void LLTextureFetch::commandSendMetrics(const std::string & caps_url, - const LLUUID & session_id, - const LLUUID & agent_id, - LLViewerAssetStats * main_stats) -{ - TFReqSendMetrics * req = new TFReqSendMetrics(caps_url, session_id, agent_id, main_stats); - - cmdEnqueue(req); -} - -void LLTextureFetch::commandDataBreak() -{ - // The pedantically correct way to implement this is to create a command - // request object in the above fashion and enqueue it. However, this is - // simple data of an advisorial not operational nature and this case - // of shared-write access is tolerable. - - LLTextureFetch::svMetricsDataBreak = true; -} - -void LLTextureFetch::cmdEnqueue(TFRequest * req) -{ - lockQueue(); - mCommands.push_back(req); - unlockQueue(); - - unpause(); -} - -LLTextureFetch::TFRequest * LLTextureFetch::cmdDequeue() -{ - TFRequest * ret = 0; - - lockQueue(); - if (! mCommands.empty()) + llinfos << "LLTextureFetch ACTIVE_HTTP:" << llendl; + for (queue_t::const_iterator iter(mHTTPTextureQueue.begin()); + mHTTPTextureQueue.end() != iter; + ++iter) { - ret = mCommands.front(); - mCommands.erase(mCommands.begin()); - } - unlockQueue(); - - return ret; -} - -void LLTextureFetch::cmdDoWork() -{ - if (mDebugPause) - { - return; // debug: don't do any work - } - - TFRequest * req = cmdDequeue(); - if (req) - { - // One request per pass should really be enough for this. - req->doWork(this); - delete req; + llinfos << " ID: " << (*iter) << llendl; } } - - -////////////////////////////////////////////////////////////////////////////// - -// Private (anonymous) class methods implementing the command scheme. - -namespace -{ - -/** - * Implements the 'Set Region' command. - * - * Thread: Thread1 (TextureFetch) - */ -bool -TFReqSetRegion::doWork(LLTextureFetch *) -{ - LLViewerAssetStatsFF::set_region_thread1(mRegionHandle); - return true; -} - - -TFReqSendMetrics::~TFReqSendMetrics() -{ - delete mMainStats; - mMainStats = 0; -} - - -/** - * Implements the 'Send Metrics' command. Takes over - * ownership of the passed LLViewerAssetStats pointer. - * - * Thread: Thread1 (TextureFetch) - */ -bool -TFReqSendMetrics::doWork(LLTextureFetch * fetcher) -{ - /* - * HTTP POST responder. Doesn't do much but tries to - * detect simple breaks in recording the metrics stream. - * - * The 'volatile' modifiers don't indicate signals, - * mmap'd memory or threads, really. They indicate that - * the referenced data is part of a pseudo-closure for - * this responder rather than being required for correct - * operation. - * - * We don't try very hard with the POST request. We give - * it one shot and that's more-or-less it. With a proper - * refactoring of the LLQueuedThread usage, these POSTs - * could be put in a request object and made more reliable. - */ - class lcl_responder : public LLHTTPClient::ResponderWithResult - { - public: - lcl_responder(LLTextureFetch * fetcher, - S32 expected_sequence, - volatile const S32 & live_sequence, - volatile bool & reporting_break, - volatile bool & reporting_started) - : mFetcher(fetcher), - mExpectedSequence(expected_sequence), - mLiveSequence(live_sequence), - mReportingBreak(reporting_break), - mReportingStarted(reporting_started) - { - mFetcher->incrCurlPOSTCount(); - } - - ~lcl_responder() - { - mFetcher->decrCurlPOSTCount(); - } - - /*virtual*/ void error(U32 status_num, const std::string & reason) - { - if (mLiveSequence == mExpectedSequence) - { - mReportingBreak = true; - } - LL_WARNS("Texture") << "Break in metrics stream due to POST failure to metrics collection service. Reason: " - << reason << LL_ENDL; - } - - /*virtual*/ void result(const LLSD & content) - { - if (mLiveSequence == mExpectedSequence) - { - mReportingBreak = false; - mReportingStarted = true; - } - } - /*virtual*/ AIHTTPTimeoutPolicy const& getHTTPTimeoutPolicy(void) const { return lcl_responder_timeout; } - /*virtual*/ char const* getName(void) const { return "lcl_responder"; } - - private: - LLTextureFetch * mFetcher; - S32 mExpectedSequence; - volatile const S32 & mLiveSequence; - volatile bool & mReportingBreak; - volatile bool & mReportingStarted; - - }; // class lcl_responder - - if (! gViewerAssetStatsThread1) - return true; - - static volatile bool reporting_started(false); - static volatile S32 report_sequence(0); - - // We've taken over ownership of the stats copy at this - // point. Get a working reference to it for merging here - // but leave it in 'this'. Destructor will rid us of it. - LLViewerAssetStats & main_stats = *mMainStats; - - // Merge existing stats into those from main, convert to LLSD - main_stats.merge(*gViewerAssetStatsThread1); - LLSD merged_llsd = main_stats.asLLSD(true); - - // Add some additional meta fields to the content - merged_llsd["session_id"] = mSessionID; - merged_llsd["agent_id"] = mAgentID; - merged_llsd["message"] = "ViewerAssetMetrics"; // Identifies the type of metrics - merged_llsd["sequence"] = report_sequence; // Sequence number - merged_llsd["initial"] = ! reporting_started; // Initial data from viewer - merged_llsd["break"] = LLTextureFetch::svMetricsDataBreak; // Break in data prior to this report - - // Update sequence number - if (S32_MAX == ++report_sequence) - report_sequence = 0; - - // Limit the size of the stats report if necessary. - merged_llsd["truncated"] = truncate_viewer_metrics(10, merged_llsd); - - if (! mCapsURL.empty()) - { - LLHTTPClient::post(mCapsURL, - merged_llsd, - new lcl_responder(fetcher, - report_sequence, - report_sequence, - LLTextureFetch::svMetricsDataBreak, - reporting_started)); - } - else - { - LLTextureFetch::svMetricsDataBreak = true; - } - - // In QA mode, Metrics submode, log the result for ease of testing - if (fetcher->isQAMode()) - { - LL_INFOS("Textures") << merged_llsd << LL_ENDL; - } - - gViewerAssetStatsThread1->reset(); - - return true; -} - -bool -truncate_viewer_metrics(int max_regions, LLSD & metrics) -{ - static const LLSD::String reg_tag("regions"); - static const LLSD::String duration_tag("duration"); - - LLSD & reg_map(metrics[reg_tag]); - if (reg_map.size() <= max_regions) - { - return false; - } - - // Build map of region hashes ordered by duration - typedef std::multimap reg_ordered_list_t; - reg_ordered_list_t regions_by_duration; - - int ind(0); - LLSD::array_const_iterator it_end(reg_map.endArray()); - for (LLSD::array_const_iterator it(reg_map.beginArray()); it_end != it; ++it, ++ind) - { - LLSD::Real duration = (*it)[duration_tag].asReal(); - regions_by_duration.insert(reg_ordered_list_t::value_type(duration, ind)); - } - - // Build a replacement regions array with the longest-persistence regions - LLSD new_region(LLSD::emptyArray()); - reg_ordered_list_t::const_reverse_iterator it2_end(regions_by_duration.rend()); - reg_ordered_list_t::const_reverse_iterator it2(regions_by_duration.rbegin()); - for (int i(0); i < max_regions && it2_end != it2; ++i, ++it2) - { - new_region.append(reg_map[it2->second]); - } - reg_map = new_region; - - return true; -} - -} // end of anonymous namespace -#endif - diff --git a/indra/newview/lltexturefetch.h b/indra/newview/lltexturefetch.h index ac36fe74b..cbf8d1b50 100644 --- a/indra/newview/lltexturefetch.h +++ b/indra/newview/lltexturefetch.h @@ -46,9 +46,6 @@ class HTTPGetResponder; class LLTextureCache; class LLImageDecodeThread; class LLHost; -#if HTTP_METRICS -class LLViewerAssetStats; -#endif // Interface class class LLTextureFetch : public LLWorkerThread @@ -98,22 +95,6 @@ public: LLTextureInfo* getTextureInfo() { return &mTextureInfo; } -#if HTTP_METRICS - // Commands available to other threads to control metrics gathering operations. - void commandSetRegion(U64 region_handle); - void commandSendMetrics(const std::string & caps_url, - const LLUUID & session_id, - const LLUUID & agent_id, - LLViewerAssetStats * main_stats); - void commandDataBreak(); - - bool isQAMode() const { return mQAMode; } - - // Curl POST counter maintenance - inline void incrCurlPOSTCount() { mCurlPOSTRequestCount++; } - inline void decrCurlPOSTCount() { mCurlPOSTRequestCount--; } -#endif - protected: void addToNetworkQueue(LLTextureFetchWorker* worker); void removeFromNetworkQueue(LLTextureFetchWorker* worker, bool cancel); @@ -129,37 +110,6 @@ private: /*virtual*/ void threadedUpdate(void); void commonUpdate(); -#if HTTP_METRICS - // Metrics command helpers - /** - * Enqueues a command request at the end of the command queue - * and wakes up the thread as needed. - * - * Takes ownership of the TFRequest object. - * - * Method locks the command queue. - */ - void cmdEnqueue(TFRequest *); - - /** - * Returns the first TFRequest object in the command queue or - * NULL if none is present. - * - * Caller acquires ownership of the object and must dispose of it. - * - * Method locks the command queue. - */ - TFRequest * cmdDequeue(); - - /** - * Processes the first command in the queue disposing of the - * request on completion. Successive calls are needed to perform - * additional commands. - * - * Method locks the command queue. - */ - void cmdDoWork(); -#endif public: LLUUID mDebugID; @@ -172,6 +122,11 @@ private: LLMutex mQueueMutex; //to protect mRequestMap only LLMutex mNetworkQueueMutex; //to protect mNetworkQueue, mHTTPTextureQueue and mCancelQueue. +public: + static LLStat sCacheHitRate; + static LLStat sCacheReadLatency; +private: + LLTextureCache* mTextureCache; LLImageDecodeThread* mImageDecodeThread; @@ -193,30 +148,6 @@ private: //debug use U32 mTotalHTTPRequests ; -#if HTTP_METRICS - // Out-of-band cross-thread command queue. This command queue - // is logically tied to LLQueuedThread's list of - // QueuedRequest instances and so must be covered by the - // same locks. - typedef std::vector command_queue_t; - command_queue_t mCommands; - - // If true, modifies some behaviors that help with QA tasks. - const bool mQAMode; - - // Count of POST requests outstanding. We maintain the count - // indirectly in the CURL request responder's ctor and dtor and - // use it when determining whether or not to sleep the thread. Can't - // use the LLCurl module's request counter as it isn't thread compatible. - // *NOTE: Don't mix Atomic and static, apr_initialize must be called first. - LLAtomic32 mCurlPOSTRequestCount; - -public: - // A probabilistically-correct indicator that the current - // attempt to log metrics follows a break in the metrics stream - // reporting due to either startup or a problem POSTing data. - static volatile bool svMetricsDataBreak; -#endif }; #endif // LL_LLTEXTUREFETCH_H diff --git a/indra/newview/llviewermessage.cpp b/indra/newview/llviewermessage.cpp index c758d8909..ca71d11a8 100644 --- a/indra/newview/llviewermessage.cpp +++ b/indra/newview/llviewermessage.cpp @@ -5179,6 +5179,18 @@ void process_sim_stats(LLMessageSystem *msg, void **user_data) case LL_SIM_STAT_IOPUMPTIME: LLViewerStats::getInstance()->mSimPumpIOMsec.addValue(stat_value); break; + case LL_SIM_STAT_PCTSCRIPTSRUN: + LLViewerStats::getInstance()->mSimPctScriptsRun.addValue(stat_value); + break; + case LL_SIM_STAT_SIMAISTEPTIMEMS: + LLViewerStats::getInstance()->mSimSimAIStepMsec.addValue(stat_value); + break; + case LL_SIM_STAT_SKIPPEDAISILSTEPS_PS: + LLViewerStats::getInstance()->mSimSimSkippedSilhouetteSteps.addValue(stat_value); + break; + case LL_SIM_STAT_PCTSTEPPEDCHARACTERS: + LLViewerStats::getInstance()->mSimSimPctSteppedCharacters.addValue(stat_value); + break; default: // Used to be a commented out warning. LL_DEBUGS("Messaging") << "Unknown stat id" << stat_id << LL_ENDL; diff --git a/indra/newview/llviewerobjectlist.cpp b/indra/newview/llviewerobjectlist.cpp index ae919f7f7..ddcb84554 100644 --- a/indra/newview/llviewerobjectlist.cpp +++ b/indra/newview/llviewerobjectlist.cpp @@ -66,6 +66,7 @@ #include "llsdutil.h" #include "llviewerregion.h" #include "llviewerstats.h" +#include "llviewerstatsrecorder.h" #include "llvovolume.h" #include "llvoavatarself.h" #include "lltoolmgr.h" @@ -113,6 +114,7 @@ extern LLPipeline gPipeline; U32 LLViewerObjectList::sSimulatorMachineIndex = 1; // Not zero deliberately, to speed up index check. std::map LLViewerObjectList::sIPAndPortToIndex; std::map LLViewerObjectList::sIndexAndLocalIDToUUID; +LLStat LLViewerObjectList::sCacheHitRate("object_cache_hits", 128); LLViewerObjectList::LLViewerObjectList() { @@ -384,11 +386,14 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, U8 compressed_dpbuffer[2048]; LLDataPackerBinaryBuffer compressed_dp(compressed_dpbuffer, 2048); LLDataPacker *cached_dpp = NULL; + LLViewerStatsRecorder& recorder = LLViewerStatsRecorder::instance(); for (i = 0; i < num_objects; i++) { + // timer is unused? LLTimer update_timer; BOOL justCreated = FALSE; + S32 msg_size = 0; if (cached) { @@ -396,6 +401,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, U32 crc; mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_ID, id, i); mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_CRC, crc, i); + msg_size += sizeof(U32) * 2; // Lookup data packer and add this id to cache miss lists if necessary. U8 cache_miss_type = LLViewerRegion::CACHE_MISS_TYPE_NONE; @@ -411,9 +417,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, else { // Cache Miss. - #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordCacheMissEvent(id, update_type, cache_miss_type); - #endif + recorder.cacheMissEvent(id, update_type, cache_miss_type, msg_size); continue; // no data packer, skip this object } @@ -433,8 +437,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, mesgsys->getBinaryDataFast(_PREHASH_ObjectData, _PREHASH_Data, compressed_dpbuffer, 0, i); compressed_dp.assignBuffer(compressed_dpbuffer, uncompressed_length); - - if (update_type != OUT_TERSE_IMPROVED) + if (update_type != OUT_TERSE_IMPROVED) // OUT_FULL_COMPRESSED only? { compressed_dp.unpackUUID(fullid, "ID"); compressed_dp.unpackU32(local_id, "LocalID"); @@ -454,9 +457,11 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, } } } - else if (update_type != OUT_FULL) + else if (update_type != OUT_FULL) // !compressed, !OUT_FULL ==> OUT_FULL_CACHED only? { mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_ID, local_id, i); + msg_size += sizeof(U32); + getUUIDFromLocal(fullid, local_id, gMessageSystem->getSenderIP(), @@ -467,10 +472,12 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, mNumUnknownUpdates++; } } - else + else // OUT_FULL only? { mesgsys->getUUIDFast(_PREHASH_ObjectData, _PREHASH_FullID, fullid, i); mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_ID, local_id, i); + msg_size += sizeof(LLUUID); + msg_size += sizeof(U32); // llinfos << "Full Update, obj " << local_id << ", global ID" << fullid << "from " << mesgsys->getSender() << llendl; } objectp = findObject(fullid); @@ -515,28 +522,33 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { if (update_type == OUT_TERSE_IMPROVED) { - // llinfos << "terse update for an unknown object:" << fullid << llendl; + // llinfos << "terse update for an unknown object (compressed):" << fullid << llendl; + recorder.objectUpdateFailure(local_id, update_type, msg_size); continue; } } - else if (cached) + else if (cached) // Cache hit only? { } else { if (update_type != OUT_FULL) { - // llinfos << "terse update for an unknown object:" << fullid << llendl; + //llinfos << "terse update for an unknown object:" << fullid << llendl; + recorder.objectUpdateFailure(local_id, update_type, msg_size); continue; } mesgsys->getU8Fast(_PREHASH_ObjectData, _PREHASH_PCode, pcode, i); + msg_size += sizeof(U8); + } #ifdef IGNORE_DEAD if (mDeadObjects.find(fullid) != mDeadObjects.end()) { mNumDeadObjectUpdates++; - // llinfos << "update for a dead object:" << fullid << llendl; + //llinfos << "update for a dead object:" << fullid << llendl; + recorder.objectUpdateFailure(local_id, update_type, msg_size); continue; } #endif @@ -553,10 +565,14 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, objectp = createObject(pcode, regionp, fullid, local_id, gMessageSystem->getSender()); if (!objectp) { + llinfos << "createObject failure for object: " << fullid << llendl; + recorder.objectUpdateFailure(local_id, update_type, msg_size); continue; } justCreated = TRUE; mNumNewObjects++; + sCacheHitRate.addValue(cached ? 100.f : 0.f); + } @@ -568,15 +584,16 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, bool bCached = false; if (compressed) { - if (update_type != OUT_TERSE_IMPROVED) + if (update_type != OUT_TERSE_IMPROVED) // OUT_FULL_COMPRESSED only? { objectp->mLocalID = local_id; } processUpdateCore(objectp, user_data, i, update_type, &compressed_dp, justCreated); - if (update_type != OUT_TERSE_IMPROVED) + if (update_type != OUT_TERSE_IMPROVED) // OUT_FULL_COMPRESSED only? { bCached = true; - objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp); + LLViewerRegion::eCacheUpdateResult result = objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp); + recorder.cacheFullUpdate(local_id, update_type, result, objectp, msg_size); } } else if (cached) @@ -592,11 +609,13 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, } processUpdateCore(objectp, user_data, i, update_type, NULL, justCreated); } - + recorder.objectUpdateEvent(local_id, update_type, objectp, msg_size); objectp->setLastUpdateType(update_type); objectp->setLastUpdateCached(bCached); } + recorder.log(0.2f); + LLVOAvatar::cullAvatarsByPixelArea(); } diff --git a/indra/newview/llviewerobjectlist.h b/indra/newview/llviewerobjectlist.h index 5a48656b7..4f67c2691 100644 --- a/indra/newview/llviewerobjectlist.h +++ b/indra/newview/llviewerobjectlist.h @@ -205,6 +205,8 @@ public: std::vector mOrphanChildren; // UUID's of orphaned objects S32 mNumOrphans; + static LLStat sCacheHitRate; + typedef std::vector > vobj_list_t; vobj_list_t mObjects; diff --git a/indra/newview/llviewerregion.cpp b/indra/newview/llviewerregion.cpp index d300694cb..be87807f1 100644 --- a/indra/newview/llviewerregion.cpp +++ b/indra/newview/llviewerregion.cpp @@ -1405,11 +1405,8 @@ void LLViewerRegion::requestCacheMisses() mCacheDirty = TRUE ; // llinfos << "KILLDEBUG Sent cache miss full " << full_count << " crc " << crc_count << llendl; - #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->beginObjectUpdateEvents(this); - LLViewerStatsRecorder::instance()->recordRequestCacheMissesEvent(full_count + crc_count); - LLViewerStatsRecorder::instance()->endObjectUpdateEvents(); - #endif + LLViewerStatsRecorder::instance().requestCacheMissesEvent(full_count + crc_count); + LLViewerStatsRecorder::instance().log(0.2f); } void LLViewerRegion::dumpCache() diff --git a/indra/newview/llviewerstats.cpp b/indra/newview/llviewerstats.cpp index eeb96dfa6..16f494715 100644 --- a/indra/newview/llviewerstats.cpp +++ b/indra/newview/llviewerstats.cpp @@ -239,6 +239,9 @@ LLViewerStats::LLViewerStats() : mSimSimPhysicsStepMsec("simsimphysicsstepmsec"), mSimSimPhysicsShapeUpdateMsec("simsimphysicsshapeupdatemsec"), mSimSimPhysicsOtherMsec("simsimphysicsothermsec"), + mSimSimAIStepMsec("simsimaistepmsec"), + mSimSimSkippedSilhouetteSteps("simsimskippedsilhouettesteps"), + mSimSimPctSteppedCharacters("simsimpctsteppedcharacters"), mSimAgentMsec("simagentmsec"), mSimImagesMsec("simimagesmsec"), mSimScriptMsec("simscriptmsec"), @@ -250,6 +253,7 @@ LLViewerStats::LLViewerStats() : mSimObjects("simobjects"), mSimActiveObjects("simactiveobjects"), mSimActiveScripts("simactivescripts"), + mSimPctScriptsRun("simpctscriptsrun"), mSimInPPS("siminpps"), mSimOutPPS("simoutpps"), mSimPendingDownloads("simpendingdownloads"), @@ -292,19 +296,19 @@ LLViewerStats::~LLViewerStats() void LLViewerStats::resetStats() { - LLViewerStats::getInstance()->mKBitStat.reset(); - LLViewerStats::getInstance()->mLayersKBitStat.reset(); - LLViewerStats::getInstance()->mObjectKBitStat.reset(); - LLViewerStats::getInstance()->mTextureKBitStat.reset(); - LLViewerStats::getInstance()->mVFSPendingOperations.reset(); - LLViewerStats::getInstance()->mAssetKBitStat.reset(); - LLViewerStats::getInstance()->mPacketsInStat.reset(); - LLViewerStats::getInstance()->mPacketsLostStat.reset(); - LLViewerStats::getInstance()->mPacketsOutStat.reset(); - LLViewerStats::getInstance()->mFPSStat.reset(); - LLViewerStats::getInstance()->mTexturePacketsStat.reset(); - - LLViewerStats::getInstance()->mAgentPositionSnaps.reset(); + LLViewerStats& stats = LLViewerStats::instance(); + stats.mKBitStat.reset(); + stats.mLayersKBitStat.reset(); + stats.mObjectKBitStat.reset(); + stats.mTextureKBitStat.reset(); + stats.mVFSPendingOperations.reset(); + stats.mAssetKBitStat.reset(); + stats.mPacketsInStat.reset(); + stats.mPacketsLostStat.reset(); + stats.mPacketsOutStat.reset(); + stats.mFPSStat.reset(); + stats.mTexturePacketsStat.reset(); + stats.mAgentPositionSnaps.reset(); } @@ -329,55 +333,55 @@ void LLViewerStats::updateFrameStats(const F64 time_diff) { if (mPacketsLostPercentStat.getCurrent() > 5.0) { - incStat(LLViewerStats::ST_LOSS_05_SECONDS, time_diff); + incStat(ST_LOSS_05_SECONDS, time_diff); } if (mSimFPS.getCurrent() < 20.f && mSimFPS.getCurrent() > 0.f) { - incStat(LLViewerStats::ST_SIM_FPS_20_SECONDS, time_diff); + incStat(ST_SIM_FPS_20_SECONDS, time_diff); } if (mSimPhysicsFPS.getCurrent() < 20.f && mSimPhysicsFPS.getCurrent() > 0.f) { - incStat(LLViewerStats::ST_PHYS_FPS_20_SECONDS, time_diff); + incStat(ST_PHYS_FPS_20_SECONDS, time_diff); } if (time_diff >= 0.5) { - incStat(LLViewerStats::ST_FPS_2_SECONDS, time_diff); + incStat(ST_FPS_2_SECONDS, time_diff); } if (time_diff >= 0.125) { - incStat(LLViewerStats::ST_FPS_8_SECONDS, time_diff); + incStat(ST_FPS_8_SECONDS, time_diff); } if (time_diff >= 0.1) { - incStat(LLViewerStats::ST_FPS_10_SECONDS, time_diff); + incStat(ST_FPS_10_SECONDS, time_diff); } if (gFrameCount && mLastTimeDiff > 0.0) { // new "stutter" meter - setStat(LLViewerStats::ST_FPS_DROP_50_RATIO, - (getStat(LLViewerStats::ST_FPS_DROP_50_RATIO) * (F64)(gFrameCount - 1) + + setStat(ST_FPS_DROP_50_RATIO, + (getStat(ST_FPS_DROP_50_RATIO) * (F64)(gFrameCount - 1) + (time_diff >= 2.0 * mLastTimeDiff ? 1.0 : 0.0)) / gFrameCount); // old stats that were never really used - setStat(LLViewerStats::ST_FRAMETIME_JITTER, - (getStat(LLViewerStats::ST_FRAMETIME_JITTER) * (gFrameCount - 1) + + setStat(ST_FRAMETIME_JITTER, + (getStat(ST_FRAMETIME_JITTER) * (gFrameCount - 1) + fabs(mLastTimeDiff - time_diff) / mLastTimeDiff) / gFrameCount); F32 average_frametime = gRenderStartTime.getElapsedTimeF32() / (F32)gFrameCount; - setStat(LLViewerStats::ST_FRAMETIME_SLEW, - (getStat(LLViewerStats::ST_FRAMETIME_SLEW) * (gFrameCount - 1) + + setStat(ST_FRAMETIME_SLEW, + (getStat(ST_FRAMETIME_SLEW) * (gFrameCount - 1) + fabs(average_frametime - time_diff) / average_frametime) / gFrameCount); F32 max_bandwidth = gViewerThrottle.getMaxBandwidth(); F32 delta_bandwidth = gViewerThrottle.getCurrentBandwidth() - max_bandwidth; - setStat(LLViewerStats::ST_DELTA_BANDWIDTH, delta_bandwidth / 1024.f); + setStat(ST_DELTA_BANDWIDTH, delta_bandwidth / 1024.f); - setStat(LLViewerStats::ST_MAX_BANDWIDTH, max_bandwidth / 1024.f); + setStat(ST_MAX_BANDWIDTH, max_bandwidth / 1024.f); } @@ -571,25 +575,20 @@ F32 gWorstLandCompression = 0.f, gWorstWaterCompression = 0.f; U32 gTotalWorldBytes = 0, gTotalObjectBytes = 0, gTotalTextureBytes = 0, gSimPingCount = 0; U32 gObjectBits = 0; F32 gAvgSimPing = 0.f; -U32 gTotalTextureBytesPerBoostLevel[LLViewerTexture::MAX_GL_IMAGE_CATEGORY] = {0}; +U32 gTotalTextureBytesPerBoostLevel[LLGLTexture::MAX_GL_IMAGE_CATEGORY] = {0}; extern U32 gVisCompared; extern U32 gVisTested; -std::map gDebugTimers; -std::map gDebugTimerLabel; +LLFrameTimer gTextureTimer; -void init_statistics() -{ - // Label debug timers - gDebugTimerLabel[0] = "Texture"; -} - -void update_statistics(U32 frame_count) +void update_statistics() { gTotalWorldBytes += gVLManager.getTotalBytes(); gTotalObjectBytes += gObjectBits / 8; + LLViewerStats& stats = LLViewerStats::instance(); + // make sure we have a valid time delta for this frame if (gFrameIntervalSeconds > 0.f) { @@ -606,51 +605,51 @@ void update_statistics(U32 frame_count) LLViewerStats::getInstance()->incStat(LLViewerStats::ST_TOOLBOX_SECONDS, gFrameIntervalSeconds); } } - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_ENABLE_VBO, (F64)gSavedSettings.getBOOL("RenderVBOEnable")); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_LIGHTING_DETAIL, (F64)gPipeline.getLightingDetail()); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_DRAW_DIST, (F64)gSavedSettings.getF32("RenderFarClip")); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_CHAT_BUBBLES, (F64)gSavedSettings.getBOOL("UseChatBubbles")); + stats.setStat(LLViewerStats::ST_ENABLE_VBO, (F64)gSavedSettings.getBOOL("RenderVBOEnable")); + stats.setStat(LLViewerStats::ST_LIGHTING_DETAIL, (F64)gPipeline.getLightingDetail()); + stats.setStat(LLViewerStats::ST_DRAW_DIST, (F64)gSavedSettings.getF32("RenderFarClip")); + stats.setStat(LLViewerStats::ST_CHAT_BUBBLES, (F64)gSavedSettings.getBOOL("UseChatBubbles")); #if 0 // 1.9.2 LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_OBJECTS, (F64)gSavedSettings.getS32("VertexShaderLevelObject")); LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_AVATAR, (F64)gSavedSettings.getBOOL("VertexShaderLevelAvatar")); LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_ENVIRONMENT, (F64)gSavedSettings.getBOOL("VertexShaderLevelEnvironment")); #endif - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_FRAME_SECS, gDebugView->mFastTimerView->getTime("Frame")); + stats.setStat(LLViewerStats::ST_FRAME_SECS, gDebugView->mFastTimerView->getTime("Frame")); F64 idle_secs = gDebugView->mFastTimerView->getTime("Idle"); F64 network_secs = gDebugView->mFastTimerView->getTime("Network"); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_UPDATE_SECS, idle_secs - network_secs); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_NETWORK_SECS, network_secs); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_IMAGE_SECS, gDebugView->mFastTimerView->getTime("Update Images")); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_REBUILD_SECS, gDebugView->mFastTimerView->getTime("Sort Draw State")); - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_RENDER_SECS, gDebugView->mFastTimerView->getTime("Geometry")); + stats.setStat(LLViewerStats::ST_UPDATE_SECS, idle_secs - network_secs); + stats.setStat(LLViewerStats::ST_NETWORK_SECS, network_secs); + stats.setStat(LLViewerStats::ST_IMAGE_SECS, gDebugView->mFastTimerView->getTime("Update Images")); + stats.setStat(LLViewerStats::ST_REBUILD_SECS, gDebugView->mFastTimerView->getTime("Sort Draw State")); + stats.setStat(LLViewerStats::ST_RENDER_SECS, gDebugView->mFastTimerView->getTime("Geometry")); LLCircuitData *cdp = gMessageSystem->mCircuitInfo.findCircuit(gAgent.getRegion()->getHost()); if (cdp) { - LLViewerStats::getInstance()->mSimPingStat.addValue(cdp->getPingDelay()); + stats.mSimPingStat.addValue(cdp->getPingDelay()); gAvgSimPing = ((gAvgSimPing * (F32)gSimPingCount) + (F32)(cdp->getPingDelay())) / ((F32)gSimPingCount + 1); gSimPingCount++; } else { - LLViewerStats::getInstance()->mSimPingStat.addValue(10000); + stats.mSimPingStat.addValue(10000); } - LLViewerStats::getInstance()->mFPSStat.addValue(1); + stats.mFPSStat.addValue(1); F32 layer_bits = (F32)(gVLManager.getLandBits() + gVLManager.getWindBits() + gVLManager.getCloudBits()); - LLViewerStats::getInstance()->mLayersKBitStat.addValue(layer_bits/1024.f); - LLViewerStats::getInstance()->mObjectKBitStat.addValue(gObjectBits/1024.f); - LLViewerStats::getInstance()->mVFSPendingOperations.addValue(LLVFile::getVFSThread()->getPending()); - LLViewerStats::getInstance()->mAssetKBitStat.addValue(gTransferManager.getTransferBitsIn(LLTCT_ASSET)/1024.f); + stats.mLayersKBitStat.addValue(layer_bits/1024.f); + stats.mObjectKBitStat.addValue(gObjectBits/1024.f); + stats.mVFSPendingOperations.addValue(LLVFile::getVFSThread()->getPending()); + stats.mAssetKBitStat.addValue(gTransferManager.getTransferBitsIn(LLTCT_ASSET)/1024.f); gTransferManager.resetTransferBitsIn(LLTCT_ASSET); if (LLAppViewer::getTextureFetch()->getNumRequests() == 0) { - gDebugTimers[0].pause(); + gTextureTimer.pause(); } else { - gDebugTimers[0].unpause(); + gTextureTimer.unpause(); } { @@ -662,7 +661,7 @@ void update_statistics(U32 frame_count) visible_avatar_frames = 1.f; avg_visible_avatars = (avg_visible_avatars * (F32)(visible_avatar_frames - 1.f) + visible_avatars) / visible_avatar_frames; } - LLViewerStats::getInstance()->setStat(LLViewerStats::ST_VISIBLE_AVATARS, (F64)avg_visible_avatars); + stats.setStat(LLViewerStats::ST_VISIBLE_AVATARS, (F64)avg_visible_avatars); } LLWorld::getInstance()->updateNetStats(); LLWorld::getInstance()->requestCacheMisses(); @@ -672,14 +671,14 @@ void update_statistics(U32 frame_count) gObjectBits = 0; // gDecodedBits = 0; - //Update bandwidth stats often because texture fetch relies on them. + // Only update texture stats periodically so that they are less noisy { - static const F32 texture_stats_freq = 0.1f; + static const F32 texture_stats_freq = 10.f; static LLFrameTimer texture_stats_timer; if (texture_stats_timer.getElapsedTimeF32() >= texture_stats_freq) { - LLViewerStats::getInstance()->mTextureKBitStat.addValue(LLViewerTextureList::sTextureBits/1024.f); - LLViewerStats::getInstance()->mTexturePacketsStat.addValue(LLViewerTextureList::sTexturePackets); + stats.mTextureKBitStat.addValue(LLViewerTextureList::sTextureBits/1024.f); + stats.mTexturePacketsStat.addValue(LLViewerTextureList::sTexturePackets); LLAppViewer::getTextureFetch()->setTextureBandwidth(LLViewerTextureList::sTextureBits/1024.f/texture_stats_timer.getElapsedTimeF32()); gTotalTextureBytes += LLViewerTextureList::sTextureBits / 8; LLViewerTextureList::sTextureBits = 0; @@ -693,7 +692,7 @@ void update_statistics(U32 frame_count) static LLFrameTimer mem_stats_timer; if (mem_stats_timer.getElapsedTimeF32() >= mem_stats_freq) { - LLViewerStats::getInstance()->mMallocStat.addValue(SGMemStat::getMalloc()/1024.f/1024.f); + stats.mMallocStat.addValue(SGMemStat::getMalloc()/1024.f/1024.f); mem_stats_timer.reset(); } } @@ -813,6 +812,7 @@ void send_stats() system["gpu_class"] = (S32)LLFeatureManager::getInstance()->getGPUClass(); system["gpu_vendor"] = gGLManager.mGLVendorShort; system["gpu_version"] = gGLManager.mDriverVersionVendorString; + system["opengl_version"] = gGLManager.mGLVersionString; LLSD &download = body["downloads"]; @@ -859,10 +859,7 @@ void send_stats() S32 window_height = gViewerWindow->getWindowHeightRaw(); S32 window_size = (window_width * window_height) / 1024; misc["string_1"] = llformat("%d", window_size); - if (gDebugTimers.find(0) != gDebugTimers.end() && gFrameTimeSeconds > 0) - { - misc["string_2"] = llformat("Texture Time: %.2f, Total Time: %.2f", gDebugTimers[0].getElapsedTimeF32(), gFrameTimeSeconds); - } + misc["string_2"] = llformat("Texture Time: %.2f, Total Time: %.2f", gTextureTimer.getElapsedTimeF32(), gFrameTimeSeconds); // misc["int_1"] = LLSD::Integer(gSavedSettings.getU32("RenderQualityPerformance")); // Steve: 1.21 // misc["int_2"] = LLSD::Integer(gFrameStalls); // Steve: 1.21 diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h index 93d482da7..264b02bf2 100644 --- a/indra/newview/llviewerstats.h +++ b/indra/newview/llviewerstats.h @@ -39,88 +39,91 @@ class LLViewerStats : public LLSingleton { public: - LLStat mKBitStat; - LLStat mLayersKBitStat; - LLStat mObjectKBitStat; - LLStat mAssetKBitStat; - LLStat mTextureKBitStat; - LLStat mVFSPendingOperations; - LLStat mObjectsDrawnStat; - LLStat mObjectsCulledStat; - LLStat mObjectsTestedStat; - LLStat mObjectsComparedStat; - LLStat mObjectsOccludedStat; - LLStat mFPSStat; - LLStat mPacketsInStat; - LLStat mPacketsLostStat; - LLStat mPacketsOutStat; - LLStat mPacketsLostPercentStat; - LLStat mTexturePacketsStat; - LLStat mActualInKBitStat; // From the packet ring (when faking a bad connection) - LLStat mActualOutKBitStat; // From the packet ring (when faking a bad connection) - LLStat mTrianglesDrawnStat; - LLStat mMallocStat; + LLStat mKBitStat, + mLayersKBitStat, + mObjectKBitStat, + mAssetKBitStat, + mTextureKBitStat, + mVFSPendingOperations, + mObjectsDrawnStat, + mObjectsCulledStat, + mObjectsTestedStat, + mObjectsComparedStat, + mObjectsOccludedStat, + mFPSStat, + mPacketsInStat, + mPacketsLostStat, + mPacketsOutStat, + mPacketsLostPercentStat, + mTexturePacketsStat, + mActualInKBitStat, // From the packet ring (when faking a bad connection) + mActualOutKBitStat, // From the packet ring (when faking a bad connection) + mTrianglesDrawnStat, + mMallocStat; // Simulator stats - LLStat mSimTimeDilation; + LLStat mSimTimeDilation, - LLStat mSimFPS; - LLStat mSimPhysicsFPS; - LLStat mSimAgentUPS; - LLStat mSimScriptEPS; + mSimFPS, + mSimPhysicsFPS, + mSimAgentUPS, + mSimScriptEPS, - LLStat mSimFrameMsec; - LLStat mSimNetMsec; - LLStat mSimSimOtherMsec; - LLStat mSimSimPhysicsMsec; + mSimFrameMsec, + mSimNetMsec, + mSimSimOtherMsec, + mSimSimPhysicsMsec, - LLStat mSimSimPhysicsStepMsec; - LLStat mSimSimPhysicsShapeUpdateMsec; - LLStat mSimSimPhysicsOtherMsec; + mSimSimPhysicsStepMsec, + mSimSimPhysicsShapeUpdateMsec, + mSimSimPhysicsOtherMsec, + mSimSimAIStepMsec, + mSimSimSkippedSilhouetteSteps, + mSimSimPctSteppedCharacters, - LLStat mSimAgentMsec; - LLStat mSimImagesMsec; - LLStat mSimScriptMsec; - LLStat mSimSpareMsec; - LLStat mSimSleepMsec; - LLStat mSimPumpIOMsec; + mSimAgentMsec, + mSimImagesMsec, + mSimScriptMsec, + mSimSpareMsec, + mSimSleepMsec, + mSimPumpIOMsec, - LLStat mSimMainAgents; - LLStat mSimChildAgents; - LLStat mSimObjects; - LLStat mSimActiveObjects; - LLStat mSimActiveScripts; + mSimMainAgents, + mSimChildAgents, + mSimObjects, + mSimActiveObjects, + mSimActiveScripts, + mSimPctScriptsRun, - LLStat mSimInPPS; - LLStat mSimOutPPS; - LLStat mSimPendingDownloads; - LLStat mSimPendingUploads; - LLStat mSimPendingLocalUploads; - LLStat mSimTotalUnackedBytes; + mSimInPPS, + mSimOutPPS, + mSimPendingDownloads, + mSimPendingUploads, + mSimPendingLocalUploads, + mSimTotalUnackedBytes, - LLStat mPhysicsPinnedTasks; - LLStat mPhysicsLODTasks; - LLStat mPhysicsMemoryAllocated; + mPhysicsPinnedTasks, + mPhysicsLODTasks, + mPhysicsMemoryAllocated, - LLStat mSimPingStat; + mSimPingStat, - LLStat mNumImagesStat; - LLStat mNumRawImagesStat; - LLStat mGLTexMemStat; - LLStat mGLBoundMemStat; - LLStat mRawMemStat; - LLStat mFormattedMemStat; + mNumImagesStat, + mNumRawImagesStat, + mGLTexMemStat, + mGLBoundMemStat, + mRawMemStat, + mFormattedMemStat, - LLStat mNumObjectsStat; - LLStat mNumActiveObjectsStat; - LLStat mNumNewObjectsStat; - LLStat mNumSizeCulledStat; - LLStat mNumVisCulledStat; + mNumObjectsStat, + mNumActiveObjectsStat, + mNumNewObjectsStat, + mNumSizeCulledStat, + mNumVisCulledStat; void resetStats(); public: - // If you change this, please also add a corresponding text label - // in statTypeToText in llviewerstats.cpp + // If you change this, please also add a corresponding text label in llviewerstats.cpp enum EStatType { ST_VERSION = 0, @@ -251,7 +254,7 @@ public: inline F32 getStdDev() const { const F32 mean = getMean(); - return (mCount == 0) ? 0.f : sqrt( mSumOfSquares/mCount - (mean * mean) ); + return (mCount < 2) ? 0.f : sqrt(llmax(0.f,mSumOfSquares/mCount - (mean * mean))); } inline U32 getCount() const @@ -291,14 +294,12 @@ private: static const F32 SEND_STATS_PERIOD = 300.0f; // The following are from (older?) statistics code found in appviewer. -void init_statistics(); void reset_statistics(); void output_statistics(void*); -void update_statistics(U32 frame_count); +void update_statistics(); void send_stats(); -extern std::map gDebugTimers; -extern std::map gDebugTimerLabel; +extern LLFrameTimer gTextureTimer; extern U32 gTotalTextureBytes; extern U32 gTotalObjectBytes; extern U32 gTotalTextureBytesPerBoostLevel[] ; diff --git a/indra/newview/llviewerstatsrecorder.cpp b/indra/newview/llviewerstatsrecorder.cpp index e9d21b484..91e485d01 100644 --- a/indra/newview/llviewerstatsrecorder.cpp +++ b/indra/newview/llviewerstatsrecorder.cpp @@ -27,7 +27,6 @@ #include "llviewerprecompiledheaders.h" #include "llviewerstatsrecorder.h" -#if LL_RECORD_VIEWER_STATS #include "llfile.h" #include "llviewerregion.h" @@ -45,9 +44,8 @@ LLViewerStatsRecorder* LLViewerStatsRecorder::sInstance = NULL; LLViewerStatsRecorder::LLViewerStatsRecorder() : mObjectCacheFile(NULL), mTimer(), - mRegionp(NULL), - mStartTime(0.f), - mProcessingTime(0.f) + mStartTime(0.0), + mLastSnapshotTime(0.0) { if (NULL != sInstance) { @@ -61,112 +59,77 @@ LLViewerStatsRecorder::~LLViewerStatsRecorder() { if (mObjectCacheFile != NULL) { + // last chance snapshot + writeToLog(0.f); LLFile::close(mObjectCacheFile); mObjectCacheFile = NULL; } } -// static -void LLViewerStatsRecorder::initClass() -{ - sInstance = new LLViewerStatsRecorder(); -} - -// static -void LLViewerStatsRecorder::cleanupClass() -{ - delete sInstance; - sInstance = NULL; -} - - -void LLViewerStatsRecorder::initStatsRecorder(LLViewerRegion *regionp) -{ - if (mObjectCacheFile == NULL) - { - mStartTime = LLTimer::getTotalTime(); - mObjectCacheFile = LLFile::fopen(STATS_FILE_NAME, "wb"); - if (mObjectCacheFile) - { // Write column headers - std::ostringstream data_msg; - data_msg << "EventTime, " - << "ProcessingTime, " - << "CacheHits, " - << "CacheFullMisses, " - << "CacheCrcMisses, " - << "FullUpdates, " - << "TerseUpdates, " - << "CacheMissRequests, " - << "CacheMissResponses, " - << "CacheUpdateDupes, " - << "CacheUpdateChanges, " - << "CacheUpdateAdds, " - << "CacheUpdateReplacements, " - << "UpdateFailures" - << "\n"; - - fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); - } - } -} - -void LLViewerStatsRecorder::beginObjectUpdateEvents(LLViewerRegion *regionp) -{ - initStatsRecorder(regionp); - mRegionp = regionp; - mProcessingTime = LLTimer::getTotalTime(); - clearStats(); -} - void LLViewerStatsRecorder::clearStats() { mObjectCacheHitCount = 0; + mObjectCacheHitSize = 0; mObjectCacheMissFullCount = 0; + mObjectCacheMissFullSize = 0; mObjectCacheMissCrcCount = 0; + mObjectCacheMissCrcSize = 0; mObjectFullUpdates = 0; + mObjectFullUpdatesSize = 0; mObjectTerseUpdates = 0; + mObjectTerseUpdatesSize = 0; mObjectCacheMissRequests = 0; mObjectCacheMissResponses = 0; + mObjectCacheMissResponsesSize = 0; mObjectCacheUpdateDupes = 0; mObjectCacheUpdateChanges = 0; mObjectCacheUpdateAdds = 0; mObjectCacheUpdateReplacements = 0; mObjectUpdateFailures = 0; + mObjectUpdateFailuresSize = 0; + mTextureFetchSize = 0; } -void LLViewerStatsRecorder::recordObjectUpdateFailure(U32 local_id, const EObjectUpdateType update_type) +void LLViewerStatsRecorder::recordObjectUpdateFailure(U32 local_id, const EObjectUpdateType update_type, S32 msg_size) { mObjectUpdateFailures++; + mObjectUpdateFailuresSize += msg_size; } -void LLViewerStatsRecorder::recordCacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type) +void LLViewerStatsRecorder::recordCacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type, S32 msg_size) { if (LLViewerRegion::CACHE_MISS_TYPE_FULL == cache_miss_type) { mObjectCacheMissFullCount++; + mObjectCacheMissFullSize += msg_size; } else { mObjectCacheMissCrcCount++; + mObjectCacheMissCrcSize += msg_size; } } -void LLViewerStatsRecorder::recordObjectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp) +void LLViewerStatsRecorder::recordObjectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp, S32 msg_size) { switch (update_type) { case OUT_FULL: mObjectFullUpdates++; + mObjectFullUpdatesSize += msg_size; break; case OUT_TERSE_IMPROVED: mObjectTerseUpdates++; + mObjectTerseUpdatesSize += msg_size; break; case OUT_FULL_COMPRESSED: mObjectCacheMissResponses++; + mObjectCacheMissResponsesSize += msg_size; break; case OUT_FULL_CACHED: mObjectCacheHitCount++; + mObjectCacheHitSize += msg_size; break; default: llwarns << "Unknown update_type" << llendl; @@ -174,7 +137,7 @@ void LLViewerStatsRecorder::recordObjectUpdateEvent(U32 local_id, const EObjectU }; } -void LLViewerStatsRecorder::recordCacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp) +void LLViewerStatsRecorder::recordCacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp, S32 msg_size) { switch (update_result) { @@ -201,9 +164,15 @@ void LLViewerStatsRecorder::recordRequestCacheMissesEvent(S32 count) mObjectCacheMissRequests += count; } -void LLViewerStatsRecorder::endObjectUpdateEvents() +void LLViewerStatsRecorder::writeToLog( F32 interval ) { - llinfos << "ILX: " + F64 delta_time = LLTimer::getTotalSeconds() - mLastSnapshotTime; + S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures; + + if ( delta_time < interval || total_objects == 0) return; + + mLastSnapshotTime = LLTimer::getTotalSeconds(); + lldebugs << "ILX: " << mObjectCacheHitCount << " hits, " << mObjectCacheMissFullCount << " full misses, " << mObjectCacheMissCrcCount << " crc misses, " @@ -218,41 +187,81 @@ void LLViewerStatsRecorder::endObjectUpdateEvents() << mObjectUpdateFailures << " update failures" << llendl; - S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures; - if (mObjectCacheFile != NULL && - total_objects > 0) + if (mObjectCacheFile == NULL) { - std::ostringstream data_msg; - F32 processing32 = (F32) ((LLTimer::getTotalTime() - mProcessingTime) / 1000.0); + mStartTime = LLTimer::getTotalSeconds(); + mObjectCacheFile = LLFile::fopen(STATS_FILE_NAME, "wb"); + if (mObjectCacheFile) + { // Write column headers + std::ostringstream data_msg; + data_msg << "EventTime(ms)\t" + << "Cache Hits\t" + << "Cache Full Misses\t" + << "Cache Crc Misses\t" + << "Full Updates\t" + << "Terse Updates\t" + << "Cache Miss Requests\t" + << "Cache Miss Responses\t" + << "Cache Update Dupes\t" + << "Cache Update Changes\t" + << "Cache Update Adds\t" + << "Cache Update Replacements\t" + << "Update Failures\t" + << "Cache Hits bps\t" + << "Cache Full Misses bps\t" + << "Cache Crc Misses bps\t" + << "Full Updates bps\t" + << "Terse Updates bps\t" + << "Cache Miss Responses bps\t" + << "Texture Fetch bps\t" + << "\n"; - data_msg << getTimeSinceStart() - << ", " << processing32 - << ", " << mObjectCacheHitCount - << ", " << mObjectCacheMissFullCount - << ", " << mObjectCacheMissCrcCount - << ", " << mObjectFullUpdates - << ", " << mObjectTerseUpdates - << ", " << mObjectCacheMissRequests - << ", " << mObjectCacheMissResponses - << ", " << mObjectCacheUpdateDupes - << ", " << mObjectCacheUpdateChanges - << ", " << mObjectCacheUpdateAdds - << ", " << mObjectCacheUpdateReplacements - << ", " << mObjectUpdateFailures - << "\n"; - - fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); + fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); + } + else + { + llwarns << "Couldn't open " << STATS_FILE_NAME << " for logging." << llendl; + return; + } } + std::ostringstream data_msg; + + data_msg << getTimeSinceStart() + << "\t " << mObjectCacheHitCount + << "\t" << mObjectCacheMissFullCount + << "\t" << mObjectCacheMissCrcCount + << "\t" << mObjectFullUpdates + << "\t" << mObjectTerseUpdates + << "\t" << mObjectCacheMissRequests + << "\t" << mObjectCacheMissResponses + << "\t" << mObjectCacheUpdateDupes + << "\t" << mObjectCacheUpdateChanges + << "\t" << mObjectCacheUpdateAdds + << "\t" << mObjectCacheUpdateReplacements + << "\t" << mObjectUpdateFailures + << "\t" << (mObjectCacheHitSize * 8 / delta_time) + << "\t" << (mObjectCacheMissFullSize * 8 / delta_time) + << "\t" << (mObjectCacheMissCrcSize * 8 / delta_time) + << "\t" << (mObjectFullUpdatesSize * 8 / delta_time) + << "\t" << (mObjectTerseUpdatesSize * 8 / delta_time) + << "\t" << (mObjectCacheMissResponsesSize * 8 / delta_time) + << "\t" << (mTextureFetchSize * 8 / delta_time) + << "\n"; + + fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); clearStats(); } F32 LLViewerStatsRecorder::getTimeSinceStart() { - return (F32) ((LLTimer::getTotalTime() - mStartTime) / 1000.0); + return (F32) (LLTimer::getTotalSeconds() - mStartTime); } -#endif +void LLViewerStatsRecorder::recordTextureFetch( S32 msg_size ) +{ + mTextureFetchSize += msg_size; +} diff --git a/indra/newview/llviewerstatsrecorder.h b/indra/newview/llviewerstatsrecorder.h index 612ac380f..d1744f491 100644 --- a/indra/newview/llviewerstatsrecorder.h +++ b/indra/newview/llviewerstatsrecorder.h @@ -35,63 +35,111 @@ #define LL_RECORD_VIEWER_STATS 0 -#if LL_RECORD_VIEWER_STATS #include "llframetimer.h" #include "llviewerobject.h" #include "llviewerregion.h" class LLMutex; -class LLViewerRegion; class LLViewerObject; -class LLViewerStatsRecorder +class LLViewerStatsRecorder : public LLSingleton { public: + LOG_CLASS(LLViewerStatsRecorder); LLViewerStatsRecorder(); ~LLViewerStatsRecorder(); - static void initClass(); - static void cleanupClass(); - static LLViewerStatsRecorder* instance() {return sInstance; } + void objectUpdateFailure(U32 local_id, const EObjectUpdateType update_type, S32 msg_size) + { +#if LL_RECORD_VIEWER_STATS + recordObjectUpdateFailure(local_id, update_type, msg_size); +#endif + } - void initStatsRecorder(LLViewerRegion *regionp); + void cacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type, S32 msg_size) + { +#if LL_RECORD_VIEWER_STATS + recordCacheMissEvent(local_id, update_type, cache_miss_type, msg_size); +#endif + } - void beginObjectUpdateEvents(LLViewerRegion *regionp); - void recordObjectUpdateFailure(U32 local_id, const EObjectUpdateType update_type); - void recordCacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type); - void recordObjectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp); - void recordCacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp); - void recordRequestCacheMissesEvent(S32 count); - void endObjectUpdateEvents(); + void objectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp, S32 msg_size) + { +#if LL_RECORD_VIEWER_STATS + recordObjectUpdateEvent(local_id, update_type, objectp, msg_size); +#endif + } + + void cacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp, S32 msg_size) + { +#if LL_RECORD_VIEWER_STATS + recordCacheFullUpdate(local_id, update_type, update_result, objectp, msg_size); +#endif + } + + void requestCacheMissesEvent(S32 count) + { +#if LL_RECORD_VIEWER_STATS + recordRequestCacheMissesEvent(count); +#endif + } + + void textureFetch(S32 msg_size) + { +#if LL_RECORD_VIEWER_STATS + recordTextureFetch(msg_size); +#endif + } + + void log(F32 interval) + { +#if LL_RECORD_VIEWER_STATS + writeToLog(interval); +#endif + } F32 getTimeSinceStart(); private: + void recordObjectUpdateFailure(U32 local_id, const EObjectUpdateType update_type, S32 msg_size); + void recordCacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type, S32 msg_size); + void recordObjectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp, S32 msg_size); + void recordCacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp, S32 msg_size); + void recordRequestCacheMissesEvent(S32 count); + void recordTextureFetch(S32 msg_size); + void writeToLog(F32 interval); + static LLViewerStatsRecorder* sInstance; LLFILE * mObjectCacheFile; // File to write data into LLFrameTimer mTimer; - LLViewerRegion* mRegionp; F64 mStartTime; - F64 mProcessingTime; + F64 mLastSnapshotTime; S32 mObjectCacheHitCount; + S32 mObjectCacheHitSize; S32 mObjectCacheMissFullCount; + S32 mObjectCacheMissFullSize; S32 mObjectCacheMissCrcCount; + S32 mObjectCacheMissCrcSize; S32 mObjectFullUpdates; + S32 mObjectFullUpdatesSize; S32 mObjectTerseUpdates; + S32 mObjectTerseUpdatesSize; S32 mObjectCacheMissRequests; S32 mObjectCacheMissResponses; + S32 mObjectCacheMissResponsesSize; S32 mObjectCacheUpdateDupes; S32 mObjectCacheUpdateChanges; S32 mObjectCacheUpdateAdds; S32 mObjectCacheUpdateReplacements; S32 mObjectUpdateFailures; + S32 mObjectUpdateFailuresSize; + S32 mTextureFetchSize; void clearStats(); }; -#endif // LL_RECORD_VIEWER_STATS #endif // LLVIEWERSTATSRECORDER_H diff --git a/indra/newview/llviewertexturelist.cpp b/indra/newview/llviewertexturelist.cpp index 981421b99..d57a05a46 100644 --- a/indra/newview/llviewertexturelist.cpp +++ b/indra/newview/llviewertexturelist.cpp @@ -980,14 +980,6 @@ F32 LLViewerTextureList::updateImagesFetchTextures(F32 max_time) break; } } - //if (fetch_count == 0) - //{ - // gDebugTimers[0].pause(); - //} - //else - //{ - // gDebugTimers[0].unpause(); - //} return image_op_timer.getElapsedTimeF32(); } diff --git a/indra/newview/llviewerwindow.cpp b/indra/newview/llviewerwindow.cpp index c5f44f342..b44870e21 100644 --- a/indra/newview/llviewerwindow.cpp +++ b/indra/newview/llviewerwindow.cpp @@ -318,27 +318,24 @@ public: static const LLCachedControl debug_show_time("DebugShowTime"); if (debug_show_time) { - const U32 y_inc2 = 15; - for (std::map::reverse_iterator iter = gDebugTimers.rbegin(); - iter != gDebugTimers.rend(); ++iter) { - S32 idx = iter->first; - LLFrameTimer& timer = iter->second; + const U32 y_inc2 = 15; + LLFrameTimer& timer = gTextureTimer; F32 time = timer.getElapsedTimeF32(); S32 hours = (S32)(time / (60*60)); S32 mins = (S32)((time - hours*(60*60)) / 60); S32 secs = (S32)((time - hours*(60*60) - mins*60)); - std::string label = gDebugTimerLabel[idx]; - if (label.empty()) label = llformat("Debug: %d", idx); - addText(xpos, ypos, llformat(" %s: %d:%02d:%02d", label.c_str(), hours,mins,secs)); ypos += y_inc2; + addText(xpos, ypos, llformat("Texture: %d:%02d:%02d", hours,mins,secs)); ypos += y_inc2; } + { F32 time = gFrameTimeSeconds; S32 hours = (S32)(time / (60*60)); S32 mins = (S32)((time - hours*(60*60)) / 60); S32 secs = (S32)((time - hours*(60*60) - mins*60)); addText(xpos, ypos, llformat("Time: %d:%02d:%02d", hours,mins,secs)); ypos += y_inc; } + } #if LL_WINDOWS static const LLCachedControl debug_show_memory("DebugShowMemory");