From 7d739fbe5b5f53fdc9dc5bfc1358906cca44fc05 Mon Sep 17 00:00:00 2001 From: "Brad Payne (Vir Linden)" Date: Thu, 5 Apr 2012 14:25:21 -0400 Subject: SH-3064 WIP - accumulate stats tied to phase timers --- indra/newview/llagentwearables.cpp | 2 +- indra/newview/llviewerstats.h | 2 +- indra/newview/llvoavatar.cpp | 106 +++++++++++++++++++++++++++++++++---- indra/newview/llvoavatar.h | 9 ++++ indra/newview/llvoavatarself.cpp | 18 +++---- 5 files changed, 116 insertions(+), 21 deletions(-) mode change 100644 => 100755 indra/newview/llviewerstats.h (limited to 'indra') diff --git a/indra/newview/llagentwearables.cpp b/indra/newview/llagentwearables.cpp index 843fe8ef5e..5bfcace707 100755 --- a/indra/newview/llagentwearables.cpp +++ b/indra/newview/llagentwearables.cpp @@ -952,7 +952,7 @@ void LLAgentWearables::processAgentInitialWearablesUpdate(LLMessageSystem* mesgs if (isAgentAvatarValid()) { - gAgentAvatarp->clearPhases(); // reset phase timers for outfit loading. + //gAgentAvatarp->clearPhases(); // reset phase timers for outfit loading. gAgentAvatarp->startPhase("process_initial_wearables_update"); gAgentAvatarp->outputRezTiming("Received initial wearables update"); } diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h old mode 100644 new mode 100755 index f91a1241fe..718fabc75a --- a/indra/newview/llviewerstats.h +++ b/indra/newview/llviewerstats.h @@ -244,7 +244,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 diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp index 58cabd1a24..abbe25175a 100755 --- a/indra/newview/llvoavatar.cpp +++ b/indra/newview/llvoavatar.cpp @@ -633,11 +633,11 @@ F32 LLVOAvatar::sLODFactor = 1.f; F32 LLVOAvatar::sPhysicsLODFactor = 1.f; BOOL LLVOAvatar::sUseImpostors = FALSE; BOOL LLVOAvatar::sJointDebug = FALSE; - F32 LLVOAvatar::sUnbakedTime = 0.f; F32 LLVOAvatar::sUnbakedUpdateTime = 0.f; F32 LLVOAvatar::sGreyTime = 0.f; F32 LLVOAvatar::sGreyUpdateTime = 0.f; +LLVOAvatar::phase_stats_t LLVOAvatar::sPhaseStats; //----------------------------------------------------------------------------- // Helper functions @@ -696,7 +696,9 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id, mSupportsAlphaLayers(FALSE), mLoadedCallbacksPaused(FALSE), mHasPelvisOffset( FALSE ), - mRenderUnloadedAvatar(LLCachedControl(gSavedSettings, "RenderUnloadedAvatar")) + mRenderUnloadedAvatar(LLCachedControl(gSavedSettings, "RenderUnloadedAvatar")), + mLastRezzedStatus(-1) + { LLMemType mt(LLMemType::MTYPE_AVATAR); //VTResume(); // VTune @@ -793,12 +795,6 @@ void LLVOAvatar::debugAvatarRezTime(std::string notification_name, std::string c << " : " << comment << llendl; - if (gAgentAvatarp && !gAgentAvatarp->isDead()) // not safe to call during ~LLVOAvatarself - { - LLSD metrics = gAgentAvatarp->metricsData(); - LL_DEBUGS("Avatar") << gAgentAvatarp->avString() << " metrics " << ll_pretty_print_sd(metrics) << LL_ENDL; - } - if (gSavedSettings.getBOOL("DebugAvatarRezTime")) { LLSD args; @@ -970,6 +966,7 @@ LLFrameTimer& LLVOAvatar::getPhaseTimer(const std::string& phase_name) void LLVOAvatar::startPhase(const std::string& phase_name) { LLFrameTimer& timer = getPhaseTimer(phase_name); + lldebugs << "startPhase " << phase_name << llendl; timer.unpause(); } @@ -978,8 +975,18 @@ void LLVOAvatar::stopPhase(const std::string& phase_name) phase_map_t::iterator iter = mPhases.find(phase_name); if (iter != mPhases.end()) { + if (iter->second.getStarted()) + { + // Going from started to paused state - record stats. + recordPhaseStat(phase_name,iter->second.getElapsedTimeF32()); + } + lldebugs << "stopPhase " << phase_name << llendl; iter->second.pause(); } + else + { + lldebugs << "stopPhase " << phase_name << " is not started, no-op" << llendl; + } } void LLVOAvatar::stopAllPhases() @@ -987,13 +994,23 @@ void LLVOAvatar::stopAllPhases() for (phase_map_t::iterator iter = mPhases.begin(); iter != mPhases.end(); ++iter) { + const std::string& phase_name = iter->first; + if (iter->second.getStarted()) + { + // Going from started to paused state - record stats. + recordPhaseStat(phase_name,iter->second.getElapsedTimeF32()); + } + lldebugs << "stopPhase (all) " << phase_name << llendl; iter->second.pause(); } } void LLVOAvatar::clearPhases() { + lldebugs << "clearPhases" << llendl; + mPhases.clear(); + mLastRezzedStatus = -1; } LLSD LLVOAvatar::dumpPhases() @@ -1001,12 +1018,39 @@ LLSD LLVOAvatar::dumpPhases() LLSD result; for (phase_map_t::iterator iter = mPhases.begin(); iter != mPhases.end(); ++iter) { - result[iter->first]["completed"] = !(iter->second.getStarted()); - result[iter->first]["elapsed"] = iter->second.getElapsedTimeF32(); + const std::string& phase_name = iter->first; + result[phase_name]["completed"] = !(iter->second.getStarted()); + result[phase_name]["elapsed"] = iter->second.getElapsedTimeF32(); +#if 0 // global stats for each phase seem like overkill here + phase_stats_t::iterator stats_iter = sPhaseStats.find(phase_name); + if (stats_iter != sPhaseStats.end()) + { + result[phase_name]["stats"] = stats_iter->second.getData(); + } +#endif } return result; } +// static +LLViewerStats::StatsAccumulator& LLVOAvatar::getPhaseStats(const std::string& phase_name) +{ + phase_stats_t::iterator it = sPhaseStats.find(phase_name); + if (it == sPhaseStats.end()) + { + LLViewerStats::StatsAccumulator new_stats; + sPhaseStats[phase_name] = new_stats; + } + return sPhaseStats[phase_name]; +} + +// static +void LLVOAvatar::recordPhaseStat(const std::string& phase_name, F32 value) +{ + LLViewerStats::StatsAccumulator& stats = getPhaseStats(phase_name); + stats.push(value); +} + void LLVOAvatar::deleteLayerSetCaches(bool clearAll) { for (U32 i = 0; i < mBakedTextureDatas.size(); i++) @@ -6544,11 +6588,53 @@ BOOL LLVOAvatar::getIsCloud() const return FALSE; } +void LLVOAvatar::updateRezzedStatusTimers() +{ + // State machine for rezzed status. Statuses are 0 = cloud, 1 = gray, 2 = textured. + // Purpose is to collect time data for each period of cloud or cloud+gray. + S32 rez_status = getRezzedStatus(); + if (rez_status != mLastRezzedStatus) + { + llinfos << avString() << "zxx rez state change: " << mLastRezzedStatus << " -> " << rez_status << llendl; + bool is_cloud_or_gray = (rez_status==0 || rez_status==1); + bool was_cloud_or_gray = (mLastRezzedStatus==0 || mLastRezzedStatus==1); + bool is_cloud = (rez_status==0); + bool was_cloud = (mLastRezzedStatus==0); + + // Non-cloud to cloud + if (is_cloud && !was_cloud) + { + // start cloud timer. + startPhase("cloud"); + } + else if (was_cloud && !is_cloud) + { + // stop cloud timer, which will capture stats. + stopPhase("cloud"); + } + + // Non-cloud-or-gray to cloud-or-gray + if (is_cloud_or_gray && !was_cloud_or_gray) + { + // start cloud-or-gray timer. + startPhase("cloud-or-gray"); + } + else if (was_cloud_or_gray && !is_cloud_or_gray) + { + // stop cloud-or-gray timer, which will capture stats. + stopPhase("cloud-or-gray"); + } + + mLastRezzedStatus = rez_status; + } +} + // call periodically to keep isFullyLoaded up to date. // returns true if the value has changed. BOOL LLVOAvatar::updateIsFullyLoaded() { const BOOL loading = getIsCloud(); + updateRezzedStatusTimers(); updateRuthTimer(loading); return processFullyLoadedChange(loading); } diff --git a/indra/newview/llvoavatar.h b/indra/newview/llvoavatar.h index 04ef8d2014..7a1b780862 100755 --- a/indra/newview/llvoavatar.h +++ b/indra/newview/llvoavatar.h @@ -48,6 +48,7 @@ #include "lltexglobalcolor.h" #include "lldriverparam.h" #include "material_codes.h" // LL_MCODE_END +#include "llviewerstats.h" extern const LLUUID ANIM_AGENT_BODY_NOISE; extern const LLUUID ANIM_AGENT_BREATHE_ROT; @@ -282,6 +283,9 @@ public: BOOL isFullyTextured() const; BOOL hasGray() const; S32 getRezzedStatus() const; // 0 = cloud, 1 = gray, 2 = fully textured. + void updateRezzedStatusTimers(); + + S32 mLastRezzedStatus; // Tracking progress of active/completed phases for activities like outfit changing. LLFrameTimer& getPhaseTimer(const std::string& phase_name); @@ -290,6 +294,8 @@ public: void stopAllPhases(); void clearPhases(); LLSD dumpPhases(); + static LLViewerStats::StatsAccumulator& getPhaseStats(const std::string& phase_name); + static void recordPhaseStat(const std::string& phase_name, F32 value); class ScopedPhaseSetter { @@ -323,8 +329,11 @@ private: LLFrameTimer mFullyLoadedTimer; LLFrameTimer mRuthTimer; + // TODO move all the phase stuff to its down data structure. typedef std::map phase_map_t; phase_map_t mPhases; + typedef std::map phase_stats_t; + static phase_stats_t sPhaseStats; protected: LLFrameTimer mInvisibleTimer; diff --git a/indra/newview/llvoavatarself.cpp b/indra/newview/llvoavatarself.cpp index c593481b40..5ba5ec8ef5 100755 --- a/indra/newview/llvoavatarself.cpp +++ b/indra/newview/llvoavatarself.cpp @@ -2430,11 +2430,11 @@ void LLVOAvatarSelf::outputRezDiagnostics() const } const F32 final_time = mDebugSelfLoadTimer.getElapsedTimeF32(); - llinfos << "REZTIME: Myself rez stats:" << llendl; - llinfos << "\t Time from avatar creation to load wearables: " << (S32)mDebugTimeWearablesLoaded << llendl; - llinfos << "\t Time from avatar creation to de-cloud: " << (S32)mDebugTimeAvatarVisible << llendl; - llinfos << "\t Time from avatar creation to de-cloud for others: " << (S32)final_time << llendl; - llinfos << "\t Load time for each texture: " << llendl; + LL_DEBUGS("Avatar") << "REZTIME: Myself rez stats:" << llendl; + LL_DEBUGS("Avatar") << "\t Time from avatar creation to load wearables: " << (S32)mDebugTimeWearablesLoaded << llendl; + LL_DEBUGS("Avatar") << "\t Time from avatar creation to de-cloud: " << (S32)mDebugTimeAvatarVisible << llendl; + LL_DEBUGS("Avatar") << "\t Time from avatar creation to de-cloud for others: " << (S32)final_time << llendl; + LL_DEBUGS("Avatar") << "\t Load time for each texture: " << llendl; for (U32 i = 0; i < LLVOAvatarDefines::TEX_NUM_INDICES; ++i) { std::stringstream out; @@ -2458,12 +2458,12 @@ void LLVOAvatarSelf::outputRezDiagnostics() const // Don't print out non-existent textures. if (j != 0) - llinfos << out.str() << llendl; + LL_DEBUGS("Avatar") << out.str() << llendl; } - llinfos << "\t Time points for each upload (start / finish)" << llendl; + LL_DEBUGS("Avatar") << "\t Time points for each upload (start / finish)" << llendl; for (U32 i = 0; i < LLVOAvatarDefines::BAKED_NUM_INDICES; ++i) { - llinfos << "\t\t (" << i << ") \t" << (S32)mDebugBakedTextureTimes[i][0] << " / " << (S32)mDebugBakedTextureTimes[i][1] << llendl; + LL_DEBUGS("Avatar") << "\t\t (" << i << ") \t" << (S32)mDebugBakedTextureTimes[i][0] << " / " << (S32)mDebugBakedTextureTimes[i][1] << llendl; } for (LLVOAvatarDefines::LLVOAvatarDictionary::BakedTextures::const_iterator baked_iter = LLVOAvatarDefines::LLVOAvatarDictionary::getInstance()->getBakedTextures().begin(); @@ -2475,7 +2475,7 @@ void LLVOAvatarSelf::outputRezDiagnostics() const if (!layerset) continue; const LLTexLayerSetBuffer *layerset_buffer = layerset->getComposite(); if (!layerset_buffer) continue; - llinfos << layerset_buffer->dumpTextureInfo() << llendl; + LL_DEBUGS("Avatar") << layerset_buffer->dumpTextureInfo() << llendl; } } -- cgit v1.2.3