From b416dcb73b1f405ebf5260cc588b07fde7ad1604 Mon Sep 17 00:00:00 2001 From: "Nyx (Neal Orman)" Date: Tue, 18 May 2010 10:20:44 -0400 Subject: adding verbose logging around your own avatar rez time. Documents load times for each component texture at each discard level, as well as baked texture upload times, and reports the timing of each texture to the console when your avatar sends out its appearance data to the server. Reviewed by Seraph, will be removed before release. -Nyx --- indra/newview/llvoavatar.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'indra/newview/llvoavatar.cpp') diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp index 2ec8ced543..c64f7b5a3e 100644 --- a/indra/newview/llvoavatar.cpp +++ b/indra/newview/llvoavatar.cpp @@ -5869,14 +5869,14 @@ void LLVOAvatar::updateRuthTimer(bool loading) const F32 LOADING_TIMEOUT = 120.f; if (mRuthTimer.getElapsedTimeF32() > LOADING_TIMEOUT) { - /* + llinfos << "Ruth Timer timeout: Missing texture data for '" << getFullname() << "' " << "( Params loaded : " << !visualParamWeightsAreDefault() << " ) " << "( Lower : " << isTextureDefined(TEX_LOWER_BAKED) << " ) " << "( Upper : " << isTextureDefined(TEX_UPPER_BAKED) << " ) " << "( Head : " << isTextureDefined(TEX_HEAD_BAKED) << " )." << llendl; - */ + LLAvatarPropertiesProcessor::getInstance()->sendAvatarTexturesRequest(getID()); mRuthTimer.reset(); } -- cgit v1.2.3 From 955473266e511d5bb155be1645a7ec464b1ce0a7 Mon Sep 17 00:00:00 2001 From: Loren Shih Date: Tue, 18 May 2010 15:15:08 -0400 Subject: AVP-72 FIXED Debug settings for gathering Welcome Island Rez time statistics Fixed memory leak. Prettied up formatting for debug readouts. Added more notifications for rez and cloud time. --- indra/newview/llvoavatar.cpp | 49 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 47 insertions(+), 2 deletions(-) (limited to 'indra/newview/llvoavatar.cpp') diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp index c64f7b5a3e..f95017b658 100644 --- a/indra/newview/llvoavatar.cpp +++ b/indra/newview/llvoavatar.cpp @@ -667,6 +667,8 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id, mTexEyeColor( NULL ), mNeedsSkin(FALSE), mUpdatePeriod(1), + mFullyLoaded(FALSE), + mPreviousFullyLoaded(FALSE), mFullyLoadedInitialized(FALSE), mSupportsAlphaLayers(FALSE) { @@ -746,8 +748,10 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id, mOohMorph = NULL; mAahMorph = NULL; - mCurrentGesticulationLevel = 0; + mCurrentGesticulationLevel = 0; + mRuthTimer.reset(); + mRuthDebugTimer.reset(); } //------------------------------------------------------------------------ @@ -755,6 +759,25 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id, //------------------------------------------------------------------------ LLVOAvatar::~LLVOAvatar() { + if (gSavedSettings.getBOOL("DebugAvatarRezTime")) + { + if (!mFullyLoaded) + { + llinfos << "AVATARREZTIME: Avatar '" << getFullname() << " left after " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds as cloud." << llendl; + LLSD args; + args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezLeftCloudNotification",args); + } + else + { + llinfos << "AVATARREZTIME: Avatar '" << getFullname() << " left." << llendl; + LLSD args; + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezLeftNotification",args); + } + + } lldebugs << "LLVOAvatar Destructor (0x" << this << ") id:" << mID << llendl; mRoot.removeAllChildren(); @@ -1269,6 +1292,7 @@ void LLVOAvatar::initInstance(void) //VTPause(); // VTune mVoiceVisualizer->setVoiceEnabled( LLVoiceClient::getInstance()->getVoiceEnabled( mID ) ); + } const LLVector3 LLVOAvatar::getRenderPosition() const @@ -2076,9 +2100,22 @@ U32 LLVOAvatar::processUpdateMessage(LLMessageSystem *mesgsys, LLMemType mt(LLMemType::MTYPE_AVATAR); LLVector3 old_vel = getVelocity(); + const BOOL has_name = !getNVPair("FirstName"); + // Do base class updates... U32 retval = LLViewerObject::processUpdateMessage(mesgsys, user_data, block_num, update_type, dp); + // Print out arrival information once we have name of avatar. + if (gSavedSettings.getBOOL("DebugAvatarRezTime")) + { + if (has_name && getNVPair("FirstName")) + { + LLSD args; + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezArrivedNotification",args); + llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' arrived." << llendl; + } + } if(retval & LLViewerObject::INVALID_UPDATE) { if (isSelf()) @@ -5863,6 +5900,14 @@ void LLVOAvatar::updateRuthTimer(bool loading) if (mPreviousFullyLoaded) { mRuthTimer.reset(); + if (gSavedSettings.getBOOL("DebugAvatarRezTime")) + { + llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' became cloud." << llendl; + LLSD args; + args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezCloudNotification",args); + } mRuthDebugTimer.reset(); } @@ -5896,7 +5941,7 @@ BOOL LLVOAvatar::processFullyLoadedChange(bool loading) { if (!mPreviousFullyLoaded && !loading && mFullyLoaded) { - llinfos << "Avatar '" << getFullname() << "' resolved in " << mRuthDebugTimer.getElapsedTimeF32() << " seconds." << llendl; + llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' resolved in " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds." << llendl; LLSD args; args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); -- cgit v1.2.3 From 3c25cf6750b5cdb554d661a0280135c0e94a2248 Mon Sep 17 00:00:00 2001 From: Loren Shih Date: Tue, 18 May 2010 17:10:44 -0400 Subject: AVP-72 FIXED Debug settings for gathering Welcome Island Rez time statistics Added timestamp for avatar rez messages. Added messaging when entering/leaving Edit Appearance Mode. --- indra/newview/llvoavatar.cpp | 40 +++++++++++++++++++++++++++++++++++----- 1 file changed, 35 insertions(+), 5 deletions(-) (limited to 'indra/newview/llvoavatar.cpp') diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp index f95017b658..46d10b0fe6 100644 --- a/indra/newview/llvoavatar.cpp +++ b/indra/newview/llvoavatar.cpp @@ -752,6 +752,7 @@ LLVOAvatar::LLVOAvatar(const LLUUID& id, mRuthTimer.reset(); mRuthDebugTimer.reset(); + mDebugExistenceTimer.reset(); } //------------------------------------------------------------------------ @@ -763,16 +764,18 @@ LLVOAvatar::~LLVOAvatar() { if (!mFullyLoaded) { - llinfos << "AVATARREZTIME: Avatar '" << getFullname() << " left after " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds as cloud." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left after " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds as cloud." << llendl; LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezLeftCloudNotification",args); } else { - llinfos << "AVATARREZTIME: Avatar '" << getFullname() << " left." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left." << llendl; LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezLeftNotification",args); } @@ -2110,10 +2113,12 @@ U32 LLVOAvatar::processUpdateMessage(LLMessageSystem *mesgsys, { if (has_name && getNVPair("FirstName")) { + mDebugExistenceTimer.reset(); LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezArrivedNotification",args); - llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' arrived." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' arrived." << llendl; } } if(retval & LLViewerObject::INVALID_UPDATE) @@ -2809,6 +2814,29 @@ void LLVOAvatar::idleUpdateNameTag(const LLVector3& root_pos_last) const BOOL is_muted = isSelf() ? FALSE : LLMuteList::getInstance()->isMuted(getID()); const BOOL is_cloud = getIsCloud(); + if (gSavedSettings.getBOOL("DebugAvatarRezTime")) + { + if (is_appearance != mNameAppearance) + { + if (is_appearance) + { + LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezEnteredAppearanceNotification",args); + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " entered appearance mode." << llendl; + } + else + { + LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); + args["NAME"] = getFullname(); + LLNotificationsUtil::add("AvatarRezLeftAppearanceNotification",args); + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left appearance mode." << llendl; + } + } + } + if (mNameString.empty() || new_name || (!title && !mTitle.empty()) || @@ -5902,8 +5930,9 @@ void LLVOAvatar::updateRuthTimer(bool loading) mRuthTimer.reset(); if (gSavedSettings.getBOOL("DebugAvatarRezTime")) { - llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' became cloud." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' became cloud." << llendl; LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezCloudNotification",args); @@ -5941,8 +5970,9 @@ BOOL LLVOAvatar::processFullyLoadedChange(bool loading) { if (!mPreviousFullyLoaded && !loading && mFullyLoaded) { - llinfos << "AVATARREZTIME: Avatar '" << getFullname() << "' resolved in " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' resolved in " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds." << llendl; LLSD args; + args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezNotification",args); -- cgit v1.2.3 From 529a88458ac774932a61e2e41bded3079520a73b Mon Sep 17 00:00:00 2001 From: Loren Shih Date: Tue, 18 May 2010 17:30:31 -0400 Subject: AVP-72 FIXED Debug settings for gathering Welcome Island Rez time statistics Superficial improvements to llinfos messaging. --- indra/newview/llvoavatar.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) (limited to 'indra/newview/llvoavatar.cpp') diff --git a/indra/newview/llvoavatar.cpp b/indra/newview/llvoavatar.cpp index 46d10b0fe6..0f4623c678 100644 --- a/indra/newview/llvoavatar.cpp +++ b/indra/newview/llvoavatar.cpp @@ -764,7 +764,7 @@ LLVOAvatar::~LLVOAvatar() { if (!mFullyLoaded) { - llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left after " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds as cloud." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' left after " << (U32)mRuthDebugTimer.getElapsedTimeF32() << " seconds as cloud." << llendl; LLSD args; args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["TIME"] = llformat("%d",(U32)mRuthDebugTimer.getElapsedTimeF32()); @@ -773,7 +773,7 @@ LLVOAvatar::~LLVOAvatar() } else { - llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' left." << llendl; LLSD args; args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); @@ -2824,7 +2824,7 @@ void LLVOAvatar::idleUpdateNameTag(const LLVector3& root_pos_last) args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezEnteredAppearanceNotification",args); - llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " entered appearance mode." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' entered appearance mode." << llendl; } else { @@ -2832,7 +2832,7 @@ void LLVOAvatar::idleUpdateNameTag(const LLVector3& root_pos_last) args["EXISTENCE"] = llformat("%d",(U32)mDebugExistenceTimer.getElapsedTimeF32()); args["NAME"] = getFullname(); LLNotificationsUtil::add("AvatarRezLeftAppearanceNotification",args); - llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << " left appearance mode." << llendl; + llinfos << "REZTIME: [ " << (U32)mDebugExistenceTimer.getElapsedTimeF32() << "sec ] Avatar '" << getFullname() << "' left appearance mode." << llendl; } } } -- cgit v1.2.3