SL-859 - exceptionally verbose logging of object state updates, likely temporary

6 files changed, 100 insertions, 19 deletions

diff --git a/indra/llcommon/llcallstack.h b/indra/llcommon/llcallstack.h
index 1f7a7689d7..5acf04a49f 100644
--- a/indra/llcommon/llcallstack.h
+++ b/indra/llcommon/llcallstack.h
@@ -78,3 +78,10 @@ struct LLContextStatus
 };
 
 LL_COMMON_API std::ostream& operator<<(std::ostream& s, const LLContextStatus& context_status);
+
+#define dumpStack(tag) \
+    if (debugLoggingEnabled(tag)) \
+    { \
+        LLCallStack cs; \
+        LL_DEBUGS(tag) << "STACK:\n" << "====================\n" << cs << "====================" << LL_ENDL; \
+    }
diff --git a/indra/newview/llviewerobject.cpp b/indra/newview/llviewerobject.cpp
index 0d515b28d0..5e88f9635f 100644
--- a/indra/newview/llviewerobject.cpp
+++ b/indra/newview/llviewerobject.cpp
@@ -105,6 +105,7 @@
 #include "llfloaterperms.h"
 #include "llvocache.h"
 #include "llcleanup.h"
+#include "llcallstack.h"
 
 //#define DEBUG_UPDATE_TYPE
 
@@ -142,6 +143,9 @@ static LLTrace::BlockTimerStatHandle FTM_CREATE_OBJECT("Create Object");
 // static
 LLViewerObject *LLViewerObject::createObject(const LLUUID &id, const LLPCode pcode, LLViewerRegion *regionp, S32 flags)
 {
+    LL_DEBUGS("AnimatedObjects") << "creating " << id << LL_ENDL;
+    dumpStack("AnimatedObjectsStack");
+    
 	LLViewerObject *res = NULL;
 	LL_RECORD_BLOCK_TIME(FTM_CREATE_OBJECT);
 	
@@ -1107,6 +1111,9 @@ U32 LLViewerObject::processUpdateMessage(LLMessageSystem *mesgsys,
 {
 	LL_DEBUGS_ONCE("SceneLoadTiming") << "Received viewer object data" << LL_ENDL;
 
+    LL_DEBUGS("AnimatedObjects") << " mesgsys " << mesgsys << " dp " << dp << " id " << getID() << " update_type " << (S32) update_type << LL_ENDL;
+    dumpStack("AnimatedObjectsStack");
+
 	U32 retval = 0x0;
 	
 	// If region is removed from the list it is also deleted.
@@ -1161,10 +1168,10 @@ U32 LLViewerObject::processUpdateMessage(LLMessageSystem *mesgsys,
 	F32 time_dilation = 1.f;
 	if(mesgsys != NULL)
 	{
-	U16 time_dilation16;
-	mesgsys->getU16Fast(_PREHASH_RegionData, _PREHASH_TimeDilation, time_dilation16);
-	time_dilation = ((F32) time_dilation16) / 65535.f;
-	mRegionp->setTimeDilation(time_dilation);
+        U16 time_dilation16;
+        mesgsys->getU16Fast(_PREHASH_RegionData, _PREHASH_TimeDilation, time_dilation16);
+        time_dilation = ((F32) time_dilation16) / 65535.f;
+        mRegionp->setTimeDilation(time_dilation);
 	}
 
 	// this will be used to determine if we've really changed position
diff --git a/indra/newview/llviewerobjectlist.cpp b/indra/newview/llviewerobjectlist.cpp
index 27cab9d575..6aac777007 100644
--- a/indra/newview/llviewerobjectlist.cpp
+++ b/indra/newview/llviewerobjectlist.cpp
@@ -68,6 +68,7 @@
 #include "u64.h"
 #include "llviewertexturelist.h"
 #include "lldatapacker.h"
+#include "llcallstack.h"
 #ifdef LL_USESYSTEMLIBS
 #include <zlib.h>
 #else
@@ -241,6 +242,10 @@ void LLViewerObjectList::processUpdateCore(LLViewerObject* objectp,
 	}
 
 	// ignore returned flags
+    LL_DEBUGS("AnimatedObjects") << "uuid " << objectp->mID << " calling processUpdateMessage " 
+                                 << objectp << " just_created " << just_created << " from_cache " << from_cache << " msg " << msg << LL_ENDL;
+    dumpStack("AnimatedObjectsStack");
+	 	
 	objectp->processUpdateMessage(msg, user_data, i, update_type, dpp);
 		
 	if (objectp->isDead())
@@ -352,7 +357,10 @@ LLViewerObject* LLViewerObjectList::processObjectUpdateFromCache(LLVOCacheEntry*
 	if (!objectp)
 	{
 		objectp = createObjectFromCache(pcode, regionp, fullid, entry->getLocalID());
-		
+
+        LL_DEBUGS("AnimatedObjects") << "uuid " << fullid << " created objectp " << objectp << LL_ENDL;
+        dumpStack("AnimatedObjectsStack");
+	 	
 		if (!objectp)
 		{
 			LL_INFOS() << "createObject failure for object: " << fullid << LL_ENDL;
@@ -471,6 +479,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
 			compressed_dp.reset();
 
 			uncompressed_length = mesgsys->getSizeFast(_PREHASH_ObjectData, i, _PREHASH_Data);
+            LL_DEBUGS("AnimatedObjects") << "got binary data from message to compressed_dpbuffer" << LL_ENDL;
 			mesgsys->getBinaryDataFast(_PREHASH_ObjectData, _PREHASH_Data, compressed_dpbuffer, 0, i);
 			compressed_dp.assignBuffer(compressed_dpbuffer, uncompressed_length);
 
@@ -520,6 +529,10 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
 				// LL_WARNS() << "update for unknown localid " << local_id << " host " << gMessageSystem->getSender() << LL_ENDL;
 				mNumUnknownUpdates++;
 			}
+            else
+            {
+                LL_DEBUGS("AnimatedObjects") << "Non-full, non-compressed update, obj " << local_id << ", global ID " << fullid << " from " << mesgsys->getSender() << LL_ENDL;
+            }
 		}
 		else // OUT_FULL only?
 		{
@@ -528,11 +541,19 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
 			mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_ID, local_id, i);
 			msg_size += sizeof(LLUUID);
 			msg_size += sizeof(U32);
-			// LL_INFOS() << "Full Update, obj " << local_id << ", global ID" << fullid << "from " << mesgsys->getSender() << LL_ENDL;
+			LL_DEBUGS("AnimatedObjects") << "Full Update, obj " << local_id << ", global ID " << fullid << " from " << mesgsys->getSender() << LL_ENDL;
 		}
 		objectp = findObject(fullid);
-        LL_DEBUGS("AnimatedObjects") << "processObjectUpdate for uuid " << fullid << " objectp " << objectp << LL_ENDL;
 
+        if (compressed)
+        {
+            LL_DEBUGS("AnimatedObjects") << "uuid " << fullid << " received compressed data from message (earlier in function)" << LL_ENDL;
+        }
+        LL_DEBUGS("AnimatedObjects") << "uuid " << fullid << " objectp " << objectp 
+                                     << " update_cache " << (S32) update_cache << " compressed " << compressed
+                                     << " update_type "  << update_type << LL_ENDL;
+        dumpStack("AnimatedObjectsStack");
+        
 		if(update_cache)
 		{
 			objectp = regionp->updateCacheEntry(local_id, objectp, update_type);
@@ -607,7 +628,10 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
 #endif
 
 			objectp = createObject(pcode, regionp, fullid, local_id, gMessageSystem->getSender());
+
             LL_DEBUGS("AnimatedObjects") << "creating object " << fullid << " result " << objectp << LL_ENDL;
+            dumpStack("AnimatedObjectsStack");
+
 			if (!objectp)
 			{
 				LL_INFOS() << "createObject failure for object: " << fullid << LL_ENDL;
@@ -702,12 +726,17 @@ void LLViewerObjectList::processCachedObjectUpdate(LLMessageSystem *mesgsys,
 		mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_CRC, crc, i);
 		mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_UpdateFlags, flags, i);
 		msg_size += sizeof(U32) * 2;
-		
+
+        LL_DEBUGS("AnimatedObjects") << "got probe for id " << id << " crc " << crc << LL_ENDL;
+        dumpStack("AnimatedObjectsStack");
+
 		// Lookup data packer and add this id to cache miss lists if necessary.
 		U8 cache_miss_type = LLViewerRegion::CACHE_MISS_TYPE_NONE;
 		if(!regionp->probeCache(id, crc, flags, cache_miss_type))
 		{
 			// Cache Miss.
+            LL_DEBUGS("AnimatedObjects") << "cache miss for id " << id << " crc " << crc << " miss type " << (S32) cache_miss_type << LL_ENDL;
+
 			recorder.cacheMissEvent(id, update_type, cache_miss_type, msg_size);
 
 			continue; // no data packer, skip this object
@@ -1974,8 +2003,9 @@ LLViewerObject *LLViewerObjectList::createObjectFromCache(const LLPCode pcode, L
 {
 	llassert_always(uuid.notNull());
 
-    LL_DEBUGS("AnimatedObjects") << "createObjectFromCache creating " << uuid << LL_ENDL;
-
+    LL_DEBUGS("AnimatedObjects") << "creating " << uuid << " local_id " << local_id << LL_ENDL;
+    dumpStack("AnimatedObjectsStack");
+    
 	LLViewerObject *objectp = LLViewerObject::createObject(uuid, pcode, regionp);
 	if (!objectp)
 	{
@@ -2009,7 +2039,9 @@ LLViewerObject *LLViewerObjectList::createObject(const LLPCode pcode, LLViewerRe
 	{
 		fullid = uuid;
 	}
+
     LL_DEBUGS("AnimatedObjects") << "createObject creating " << fullid << LL_ENDL;
+    dumpStack("AnimatedObjectsStack");
 
 	LLViewerObject *objectp = LLViewerObject::createObject(fullid, pcode, regionp);
 	if (!objectp)
diff --git a/indra/newview/llviewerregion.cpp b/indra/newview/llviewerregion.cpp
index 2da4f8e427..efaa327af6 100644
--- a/indra/newview/llviewerregion.cpp
+++ b/indra/newview/llviewerregion.cpp
@@ -78,6 +78,7 @@
 #include "llcoros.h"
 #include "lleventcoro.h"
 #include "llcorehttputil.h"
+#include "llcallstack.h"
 
 #ifdef LL_WINDOWS
 	#pragma warning(disable:4355)
@@ -1252,7 +1253,7 @@ void LLViewerRegion::updateVisibleEntries(F32 max_time)
 		LLPointer<LLViewerOctreeGroup> group = *group_iter;
 		if(group->getNumRefs() < 3 || //group to be deleted
 			!group->getOctreeNode() || group->isEmpty()) //group empty
-{
+        {
 			continue;
 		}
 
@@ -2136,6 +2137,24 @@ void LLViewerRegion::getInfo(LLSD& info)
 	info["Region"]["Handle"]["y"] = (LLSD::Integer)y;
 }
 
+void LLViewerRegion::requestSimulatorFeatures()
+{
+    // kick off a request for simulator features
+    std::string url = getCapability("SimulatorFeatures");
+    if (!url.empty())
+    {
+        std::string coroname =
+            LLCoros::instance().launch("LLViewerRegionImpl::requestSimulatorFeatureCoro",
+                                       boost::bind(&LLViewerRegionImpl::requestSimulatorFeatureCoro, mImpl, url, getHandle()));
+        
+        LL_INFOS("AppInit", "SimulatorFeatures") << "Launching " << coroname << " requesting simulator features from " << url << LL_ENDL;
+    }
+    else
+    {
+        LL_WARNS("AppInit", "SimulatorFeatures") << "SimulatorFeatures cap not set" << LL_ENDL;
+    }
+}
+
 boost::signals2::connection LLViewerRegion::setSimulatorFeaturesReceivedCallback(const caps_received_signal_t::slot_type& cb)
 {
 	return mSimulatorFeaturesReceivedSignal.connect(cb);
@@ -2213,7 +2232,7 @@ void LLViewerRegion::decodeBoundingInfo(LLVOCacheEntry* entry)
 	{
 		LLViewerRegion* old_regionp = ((LLDrawable*)entry->getEntry()->getDrawable())->getRegion();
 		if(old_regionp != this && old_regionp)
-{
+        {
 			LLViewerObject* obj = ((LLDrawable*)entry->getEntry()->getDrawable())->getVObj();
 			if(obj)
 			{
@@ -2376,12 +2395,18 @@ LLViewerRegion::eCacheUpdateResult LLViewerRegion::cacheFullUpdate(LLDataPackerB
 		// we've seen this object before
 		if (entry->getCRC() == crc)
 		{
+            LL_DEBUGS("AnimatedObjects") << " got dupe for local_id " << local_id << LL_ENDL;
+            dumpStack("AnimatedObjectsStack");
+
 			// Record a hit
 			entry->recordDupe();
 			result = CACHE_UPDATE_DUPE;
 		}
 		else //CRC changed
 		{
+            LL_DEBUGS("AnimatedObjects") << " got update for local_id " << local_id << LL_ENDL;
+            dumpStack("AnimatedObjectsStack");
+
 			// Update the cache entry
 			entry->updateEntry(crc, dp);
 
@@ -2392,6 +2417,9 @@ LLViewerRegion::eCacheUpdateResult LLViewerRegion::cacheFullUpdate(LLDataPackerB
 	}
 	else
 	{
+        LL_DEBUGS("AnimatedObjects") << " got first notification for local_id " << local_id << LL_ENDL;
+        dumpStack("AnimatedObjectsStack");
+
 		// we haven't seen this object before
 		// Create new entry and add to map
 		result = CACHE_UPDATE_ADDED;
@@ -2496,7 +2524,7 @@ bool LLViewerRegion::probeCache(U32 local_id, U32 crc, U32 flags, U8 &cache_miss
 			// Record a hit
 			mRegionCacheHitCount++;
 			entry->recordHit();
-		cache_miss_type = CACHE_MISS_TYPE_NONE;
+            cache_miss_type = CACHE_MISS_TYPE_NONE;
 			entry->setUpdateFlags(flags);
 			
 			if(entry->isState(LLVOCacheEntry::ACTIVE))
@@ -2519,12 +2547,14 @@ bool LLViewerRegion::probeCache(U32 local_id, U32 crc, U32 flags, U8 &cache_miss
 			// LL_INFOS() << "CRC miss for " << local_id << LL_ENDL;
 
 			addCacheMiss(local_id, CACHE_MISS_TYPE_CRC);
+            cache_miss_type = CACHE_MISS_TYPE_CRC;
 		}
 	}
 	else
 	{
 		// LL_INFOS() << "Cache miss for " << local_id << LL_ENDL;
 		addCacheMiss(local_id, CACHE_MISS_TYPE_FULL);
+        cache_miss_type = CACHE_MISS_TYPE_FULL;
 	}
 
 	return false;
@@ -2561,6 +2591,9 @@ void LLViewerRegion::requestCacheMisses()
 		msg->nextBlockFast(_PREHASH_ObjectData);
 		msg->addU8Fast(_PREHASH_CacheMissType, (*iter).mType);
 		msg->addU32Fast(_PREHASH_ID, (*iter).mID);
+
+        LL_DEBUGS("AnimatedObjects") << "Requesting cache missed object " << (*iter).mID << LL_ENDL;
+        
 		blocks++;
 
 		if (blocks >= 255)
@@ -2955,12 +2988,8 @@ void LLViewerRegion::setCapability(const std::string& name, const std::string& u
 	}
 	else if (name == "SimulatorFeatures")
 	{
-		// kick off a request for simulator features
-        std::string coroname =
-            LLCoros::instance().launch("LLViewerRegionImpl::requestSimulatorFeatureCoro",
-            boost::bind(&LLViewerRegionImpl::requestSimulatorFeatureCoro, mImpl, url, getHandle()));
-
-        LL_INFOS("AppInit", "SimulatorFeatures") << "Launching " << coroname << " requesting simulator features from " << url << LL_ENDL;
+        mImpl->mCapabilities["SimulatorFeatures"] = url;
+        requestSimulatorFeatures();
 	}
 	else
 	{
diff --git a/indra/newview/llviewerregion.h b/indra/newview/llviewerregion.h
index 69fb9c4d4e..69fa42c1c8 100644
--- a/indra/newview/llviewerregion.h
+++ b/indra/newview/llviewerregion.h
@@ -305,6 +305,7 @@ public:
 	bool meshUploadEnabled() const;
 
 	// has region received its simulator features list? Requires an additional query after caps received.
+    void requestSimulatorFeatures();
 	void setSimulatorFeaturesReceived(bool);
 	bool simulatorFeaturesReceived() const;
 	boost::signals2::connection setSimulatorFeaturesReceivedCallback(const caps_received_signal_t::slot_type& cb);
diff --git a/indra/newview/llvovolume.cpp b/indra/newview/llvovolume.cpp
index aa50122ff0..3d1cfcfa6b 100644
--- a/indra/newview/llvovolume.cpp
+++ b/indra/newview/llvovolume.cpp
@@ -83,6 +83,7 @@
 #include "llanimationstates.h"
 #include "llinventorytype.h"
 #include "llviewerinventory.h"
+#include "llcallstack.h"
 
 const F32 FORCE_SIMPLE_RENDER_AREA = 512.f;
 const F32 FORCE_CULL_AREA = 8.f;
@@ -308,6 +309,7 @@ U32 LLVOVolume::processUpdateMessage(LLMessageSystem *mesgsys,
 										  U32 block_num, EObjectUpdateType update_type,
 										  LLDataPacker *dp)
 {
+	 	
 	LLColor4U color;
 	const S32 teDirtyBits = (TEM_CHANGE_TEXTURE|TEM_CHANGE_COLOR|TEM_CHANGE_MEDIA);
 
@@ -321,6 +323,9 @@ U32 LLVOVolume::processUpdateMessage(LLMessageSystem *mesgsys,
 		LLSculptParams *sculpt_params = (LLSculptParams *)getParameterEntry(LLNetworkData::PARAMS_SCULPT);
 		sculpt_id = sculpt_params->getSculptTexture();
 		sculpt_type = sculpt_params->getSculptType();
+
+        LL_DEBUGS("AnimatedObjects") << "uuid " << mID << " set sculpt_id " << sculpt_id << LL_ENDL;
+        dumpStack("AnimatedObjectsStack");
 	}
 
 	if (!dp)