From 4a5ad357930f0bede4d84b9810978e9d0c5d268b Mon Sep 17 00:00:00 2001 From: Dave Parks Date: Fri, 20 Jul 2012 11:42:15 -0500 Subject: MAINT-570 Remove unused memory tracking system LLMemType --- indra/newview/llappviewer.cpp | 6 ------ 1 file changed, 6 deletions(-) (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index 062551a3e8..ba2150e277 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -1183,7 +1183,6 @@ static LLFastTimer::DeclareTimer FTM_AGENT_UPDATE("Update"); bool LLAppViewer::mainLoop() { - LLMemType mt1(LLMemType::MTYPE_MAIN); mMainloopTimeout = new LLWatchdogTimeout(); //------------------------------------------- @@ -1283,7 +1282,6 @@ bool LLAppViewer::mainLoop() && (gHeadlessClient || !gViewerWindow->getShowProgress()) && !gFocusMgr.focusLocked()) { - LLMemType mjk(LLMemType::MTYPE_JOY_KEY); joystick->scanJoystick(); gKeyboard->scanKeyboard(); } @@ -1297,7 +1295,6 @@ bool LLAppViewer::mainLoop() if (gAres != NULL && gAres->isInitialized()) { - LLMemType mt_ip(LLMemType::MTYPE_IDLE_PUMP); pingMainloopTimeout("Main:ServicePump"); LLFastTimer t4(FTM_PUMP); { @@ -1347,7 +1344,6 @@ bool LLAppViewer::mainLoop() // Sleep and run background threads { - LLMemType mt_sleep(LLMemType::MTYPE_SLEEP); LLFastTimer t2(FTM_SLEEP); // yield some time to the os based on command line option @@ -4110,7 +4106,6 @@ static LLFastTimer::DeclareTimer FTM_VLMANAGER("VL Manager"); /////////////////////////////////////////////////////// void LLAppViewer::idle() { - LLMemType mt_idle(LLMemType::MTYPE_IDLE); pingMainloopTimeout("Main:Idle"); // Update frame timers @@ -4705,7 +4700,6 @@ static LLFastTimer::DeclareTimer FTM_CHECK_REGION_CIRCUIT("Check Region Circuit" void LLAppViewer::idleNetwork() { - LLMemType mt_in(LLMemType::MTYPE_IDLE_NETWORK); pingMainloopTimeout("idleNetwork"); gObjectList.mNumNewObjects = 0; -- cgit v1.3 From 5d32e23a11f272a2cdf8b6aac106534b6814ea98 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 12 Jul 2012 22:35:51 -0700 Subject: SH-3275 WIP Run viewer metrics for object update messages improved update logging API and output format --- indra/newview/app_settings/logcontrol.xml | 20 +++- indra/newview/llappviewer.cpp | 8 -- indra/newview/llviewerobjectlist.cpp | 37 ++++-- indra/newview/llviewerregion.cpp | 6 +- indra/newview/llviewerstatsrecorder.cpp | 188 +++++++++++++++++------------- indra/newview/llviewerstatsrecorder.h | 37 +++--- 6 files changed, 174 insertions(+), 122 deletions(-) (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/newview/app_settings/logcontrol.xml b/indra/newview/app_settings/logcontrol.xml index 64122bbb6c..8636ba1090 100644 --- a/indra/newview/app_settings/logcontrol.xml +++ b/indra/newview/app_settings/logcontrol.xml @@ -48,6 +48,24 @@ --> - + + level + NONE + functions + + + classes + + LLViewerStatsRecorder + + files + + + tags + + + + + diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index ed04b5bf38..c02bc882ea 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -719,10 +719,6 @@ bool LLAppViewer::init() mAlloc.setProfilingEnabled(gSavedSettings.getBOOL("MemProfiling")); -#if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::initClass(); -#endif - // *NOTE:Mani - LLCurl::initClass is not thread safe. // Called before threads are created. LLCurl::initClass(gSavedSettings.getF32("CurlRequestTimeOut"), @@ -1894,10 +1890,6 @@ bool LLAppViewer::cleanup() LLMetricPerformanceTesterBasic::cleanClass() ; -#if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::cleanupClass(); -#endif - llinfos << "Cleaning up Media and Textures" << llendflush; //Note: diff --git a/indra/newview/llviewerobjectlist.cpp b/indra/newview/llviewerobjectlist.cpp index 54ccfb9aae..b010ac9aa7 100644 --- a/indra/newview/llviewerobjectlist.cpp +++ b/indra/newview/llviewerobjectlist.cpp @@ -334,6 +334,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, U64 region_handle; mesgsys->getU64Fast(_PREHASH_RegionData, _PREHASH_RegionHandle, region_handle); + LLViewerRegion *regionp = LLWorld::getInstance()->getRegionFromHandle(region_handle); if (!regionp) @@ -345,9 +346,9 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, U8 compressed_dpbuffer[2048]; LLDataPackerBinaryBuffer compressed_dp(compressed_dpbuffer, 2048); LLDataPacker *cached_dpp = NULL; - + LLViewerStatsRecorder& recorder = LLViewerStatsRecorder::instance(); #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->beginObjectUpdateEvents(regionp); + recorder.beginObjectUpdateEvents(1.f); #endif for (i = 0; i < num_objects; i++) @@ -355,6 +356,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, // timer is unused? LLTimer update_timer; BOOL justCreated = FALSE; + S32 msg_size = 0; if (cached) { @@ -362,6 +364,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; @@ -377,9 +380,9 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, else { // Cache Miss. - #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordCacheMissEvent(id, update_type, cache_miss_type); - #endif +#if LL_RECORD_VIEWER_STATS + recorder.recordCacheMissEvent(id, update_type, cache_miss_type, msg_size); +#endif continue; // no data packer, skip this object } @@ -391,10 +394,12 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, S32 compressed_length; compressed_dp.reset(); + U32 flags = 0; if (update_type != OUT_TERSE_IMPROVED) // OUT_FULL_COMPRESSED only? { mesgsys->getU32Fast(_PREHASH_ObjectData, _PREHASH_UpdateFlags, flags, i); + msg_size += sizeof(U32); } // I don't think we ever use this flag from the server. DK 2010/12/09 @@ -402,6 +407,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { //llinfos << "TEST: flags & FLAGS_ZLIB_COMPRESSED" << llendl; compressed_length = mesgsys->getSizeFast(_PREHASH_ObjectData, i, _PREHASH_Data); + msg_size += compressed_length; mesgsys->getBinaryDataFast(_PREHASH_ObjectData, _PREHASH_Data, compbuffer, 0, i); uncompressed_length = 2048; uncompress(compressed_dpbuffer, (unsigned long *)&uncompressed_length, @@ -411,6 +417,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, else { uncompressed_length = mesgsys->getSizeFast(_PREHASH_ObjectData, i, _PREHASH_Data); + msg_size += uncompressed_length; mesgsys->getBinaryDataFast(_PREHASH_ObjectData, _PREHASH_Data, compressed_dpbuffer, 0, i); compressed_dp.assignBuffer(compressed_dpbuffer, uncompressed_length); } @@ -439,6 +446,8 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, 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(), @@ -453,6 +462,8 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { 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); @@ -499,7 +510,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { // llinfos << "terse update for an unknown object (compressed):" << fullid << llendl; #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordObjectUpdateFailure(local_id, update_type); + recorder.recordObjectUpdateFailure(local_id, update_type, msg_size); #endif continue; } @@ -513,12 +524,14 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { //llinfos << "terse update for an unknown object:" << fullid << llendl; #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordObjectUpdateFailure(local_id, update_type); + recorder.recordObjectUpdateFailure(local_id, update_type, msg_size); #endif continue; } mesgsys->getU8Fast(_PREHASH_ObjectData, _PREHASH_PCode, pcode, i); + msg_size += sizeof(U8); + } #ifdef IGNORE_DEAD if (mDeadObjects.find(fullid) != mDeadObjects.end()) @@ -526,7 +539,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, mNumDeadObjectUpdates++; //llinfos << "update for a dead object:" << fullid << llendl; #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordObjectUpdateFailure(local_id, update_type); + recorder.recordObjectUpdateFailure(local_id, update_type, msg_size); #endif continue; } @@ -537,7 +550,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, { llinfos << "createObject failure for object: " << fullid << llendl; #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordObjectUpdateFailure(local_id, update_type); + recorder.recordObjectUpdateFailure(local_id, update_type, msg_size); #endif continue; } @@ -566,7 +579,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, bCached = true; #if LL_RECORD_VIEWER_STATS LLViewerRegion::eCacheUpdateResult result = objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp); - LLViewerStatsRecorder::instance()->recordCacheFullUpdate(local_id, update_type, result, objectp); + recorder.recordCacheFullUpdate(local_id, update_type, result, objectp, msg_size); #else objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp); #endif @@ -586,14 +599,14 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys, processUpdateCore(objectp, user_data, i, update_type, NULL, justCreated); } #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->recordObjectUpdateEvent(local_id, update_type, objectp); + recorder.recordObjectUpdateEvent(local_id, update_type, objectp, msg_size); #endif objectp->setLastUpdateType(update_type); objectp->setLastUpdateCached(bCached); } #if LL_RECORD_VIEWER_STATS - LLViewerStatsRecorder::instance()->endObjectUpdateEvents(); + recorder.endObjectUpdateEvents(); #endif LLVOAvatar::cullAvatarsByPixelArea(); diff --git a/indra/newview/llviewerregion.cpp b/indra/newview/llviewerregion.cpp index e3cb985ddb..0e2927cea4 100644 --- a/indra/newview/llviewerregion.cpp +++ b/indra/newview/llviewerregion.cpp @@ -1318,9 +1318,9 @@ 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(); + LLViewerStatsRecorder::instance().beginObjectUpdateEvents(1.f); + LLViewerStatsRecorder::instance().recordRequestCacheMissesEvent(full_count + crc_count); + LLViewerStatsRecorder::instance().endObjectUpdateEvents(); #endif } diff --git a/indra/newview/llviewerstatsrecorder.cpp b/indra/newview/llviewerstatsrecorder.cpp index e9d21b4848..cfb446fe45 100644 --- a/indra/newview/llviewerstatsrecorder.cpp +++ b/indra/newview/llviewerstatsrecorder.cpp @@ -45,9 +45,10 @@ LLViewerStatsRecorder* LLViewerStatsRecorder::sInstance = NULL; LLViewerStatsRecorder::LLViewerStatsRecorder() : mObjectCacheFile(NULL), mTimer(), - mRegionp(NULL), - mStartTime(0.f), - mProcessingTime(0.f) + mStartTime(0.0), + mProcessingStartTime(0.0), + mProcessingTotalTime(0.0), + mLastSnapshotTime(0.0) { if (NULL != sInstance) { @@ -61,112 +62,114 @@ LLViewerStatsRecorder::~LLViewerStatsRecorder() { if (mObjectCacheFile != NULL) { + // last chance snapshot + takeSnapshot(); 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) +void LLViewerStatsRecorder::beginObjectUpdateEvents(F32 interval) { + mSnapshotInterval = interval; if (mObjectCacheFile == NULL) { - mStartTime = LLTimer::getTotalTime(); + mStartTime = LLTimer::getTotalSeconds(); 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" + data_msg << "EventTime(ms), " + << "Processing Time(ms), " + << "Cache Hits, " + << "Cache Full Misses, " + << "Cache Crc Misses, " + << "Full Updates, " + << "Terse Updates, " + << "Cache Miss Requests, " + << "Cache Miss Responses, " + << "Cache Update Dupes, " + << "Cache Update Changes, " + << "Cache Update Adds, " + << "Cache Update Replacements, " + << "Update Failures, " + << "Cache Hits bps, " + << "Cache Full Misses bps, " + << "Cache Crc Misses bps, " + << "Full Updates bps, " + << "Terse Updates bps, " + << "Cache Miss Responses bps, " << "\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(); + mProcessingStartTime = LLTimer::getTotalSeconds(); } 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; } -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 +177,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) { @@ -203,53 +206,72 @@ void LLViewerStatsRecorder::recordRequestCacheMissesEvent(S32 count) void LLViewerStatsRecorder::endObjectUpdateEvents() { - llinfos << "ILX: " - << mObjectCacheHitCount << " hits, " - << mObjectCacheMissFullCount << " full misses, " - << mObjectCacheMissCrcCount << " crc misses, " - << mObjectFullUpdates << " full updates, " - << mObjectTerseUpdates << " terse updates, " - << mObjectCacheMissRequests << " cache miss requests, " - << mObjectCacheMissResponses << " cache miss responses, " - << mObjectCacheUpdateDupes << " cache update dupes, " - << mObjectCacheUpdateChanges << " cache update changes, " - << mObjectCacheUpdateAdds << " cache update adds, " - << mObjectCacheUpdateReplacements << " cache update replacements, " - << mObjectUpdateFailures << " update failures" - << llendl; + mProcessingTotalTime += LLTimer::getTotalSeconds() - mProcessingStartTime; + takeSnapshot(); +} - S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures; - if (mObjectCacheFile != NULL && - total_objects > 0) +void LLViewerStatsRecorder::takeSnapshot() +{ + F64 delta_time = LLTimer::getTotalSeconds() - mLastSnapshotTime; + if ( delta_time > mSnapshotInterval) { - std::ostringstream data_msg; - F32 processing32 = (F32) ((LLTimer::getTotalTime() - mProcessingTime) / 1000.0); + mLastSnapshotTime = LLTimer::getTotalSeconds(); + llinfos << "ILX: " + << mObjectCacheHitCount << " hits, " + << mObjectCacheMissFullCount << " full misses, " + << mObjectCacheMissCrcCount << " crc misses, " + << mObjectFullUpdates << " full updates, " + << mObjectTerseUpdates << " terse updates, " + << mObjectCacheMissRequests << " cache miss requests, " + << mObjectCacheMissResponses << " cache miss responses, " + << mObjectCacheUpdateDupes << " cache update dupes, " + << mObjectCacheUpdateChanges << " cache update changes, " + << mObjectCacheUpdateAdds << " cache update adds, " + << mObjectCacheUpdateReplacements << " cache update replacements, " + << mObjectUpdateFailures << " update failures" + << llendl; - data_msg << getTimeSinceStart() - << ", " << processing32 - << ", " << mObjectCacheHitCount - << ", " << mObjectCacheMissFullCount - << ", " << mObjectCacheMissCrcCount - << ", " << mObjectFullUpdates - << ", " << mObjectTerseUpdates - << ", " << mObjectCacheMissRequests - << ", " << mObjectCacheMissResponses - << ", " << mObjectCacheUpdateDupes - << ", " << mObjectCacheUpdateChanges - << ", " << mObjectCacheUpdateAdds - << ", " << mObjectCacheUpdateReplacements - << ", " << mObjectUpdateFailures - << "\n"; + S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures; + if (mObjectCacheFile != NULL && + total_objects > 0) + { + std::ostringstream data_msg; - fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); - } + F32 processing32 = (F32) mProcessingTotalTime; + mProcessingTotalTime = 0.0; - clearStats(); + data_msg << getTimeSinceStart() + << ", " << processing32 + << ", " << mObjectCacheHitCount + << ", " << mObjectCacheMissFullCount + << ", " << mObjectCacheMissCrcCount + << ", " << mObjectFullUpdates + << ", " << mObjectTerseUpdates + << ", " << mObjectCacheMissRequests + << ", " << mObjectCacheMissResponses + << ", " << mObjectCacheUpdateDupes + << ", " << mObjectCacheUpdateChanges + << ", " << mObjectCacheUpdateAdds + << ", " << mObjectCacheUpdateReplacements + << ", " << mObjectUpdateFailures + << ", " << (mObjectCacheHitSize * 8 / delta_time) + << ", " << (mObjectCacheMissFullSize * 8 / delta_time) + << ", " << (mObjectCacheMissCrcSize * 8 / delta_time) + << ", " << (mObjectFullUpdatesSize * 8 / delta_time) + << ", " << (mObjectTerseUpdatesSize * 8 / delta_time) + << ", " << (mObjectCacheMissResponsesSize * 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 diff --git a/indra/newview/llviewerstatsrecorder.h b/indra/newview/llviewerstatsrecorder.h index 612ac380f7..09530b13eb 100644 --- a/indra/newview/llviewerstatsrecorder.h +++ b/indra/newview/llviewerstatsrecorder.h @@ -32,7 +32,7 @@ // for analysis. // This is normally 0. Set to 1 to enable viewer stats recording -#define LL_RECORD_VIEWER_STATS 0 +#define LL_RECORD_VIEWER_STATS 1 #if LL_RECORD_VIEWER_STATS @@ -41,52 +41,59 @@ #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 beginObjectUpdateEvents(F32 interval); - void initStatsRecorder(LLViewerRegion *regionp); - - 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 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 endObjectUpdateEvents(); F32 getTimeSinceStart(); private: + void takeSnapshot(); + static LLViewerStatsRecorder* sInstance; LLFILE * mObjectCacheFile; // File to write data into LLFrameTimer mTimer; - LLViewerRegion* mRegionp; F64 mStartTime; - F64 mProcessingTime; + F64 mProcessingStartTime; + F64 mProcessingTotalTime; + F64 mSnapshotInterval; + 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; void clearStats(); -- cgit v1.3 From df7d6c90758eef95f2c8c004611add495b8a5eee Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Wed, 18 Jul 2012 12:37:52 -0700 Subject: SH-3275 WIP Run viewer metrics for object update messages continued clean up of llstats stuff --- indra/newview/llappviewer.cpp | 6 +- indra/newview/llstartup.cpp | 2 +- indra/newview/llsurface.cpp | 2 - indra/newview/llsurface.h | 3 - indra/newview/lltexturefetch.cpp | 8 +- indra/newview/llviewermenu.cpp | 17 --- indra/newview/llviewerstats.cpp | 194 ++++------------------------------ indra/newview/llviewerstats.h | 157 +++++++++++++-------------- indra/newview/llviewertexturelist.cpp | 8 -- indra/newview/llviewerwindow.cpp | 20 ++-- indra/newview/llvlcomposition.cpp | 2 - 11 files changed, 108 insertions(+), 311 deletions(-) (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index c02bc882ea..161cc418dd 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -785,9 +785,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. @@ -4208,7 +4205,6 @@ void LLAppViewer::idle() // of SEND_STATS_PERIOD so that the initial stats report will // be sent immediately. static LLFrameStatsTimer viewer_stats_timer(SEND_STATS_PERIOD); - reset_statistics(); // Update session stats every large chunk of time // *FIX: (???) SAMANTHA @@ -4268,7 +4264,7 @@ void LLAppViewer::idle() idle_afk_check(); // Update statistics for this frame - update_statistics(gFrameCount); + update_statistics(); } //////////////////////////////////////// diff --git a/indra/newview/llstartup.cpp b/indra/newview/llstartup.cpp index 6b0fc26db7..77d0932fc0 100644 --- a/indra/newview/llstartup.cpp +++ b/indra/newview/llstartup.cpp @@ -1394,7 +1394,7 @@ bool idle_startup() display_startup(); //reset statistics - LLViewerStats::getInstance()->resetStats(); + LLViewerStats::instance().resetStats(); display_startup(); // diff --git a/indra/newview/llsurface.cpp b/indra/newview/llsurface.cpp index 66df7dae3e..3bd2d4cabc 100644 --- a/indra/newview/llsurface.cpp +++ b/indra/newview/llsurface.cpp @@ -61,8 +61,6 @@ LLColor4U MAX_WATER_COLOR(0, 48, 96, 240); S32 LLSurface::sTextureSize = 256; -S32 LLSurface::sTexelsUpdated = 0; -F32 LLSurface::sTextureUpdateTime = 0.f; // ---------------- LLSurface:: Public Members --------------- diff --git a/indra/newview/llsurface.h b/indra/newview/llsurface.h index a4ef4fe2de..eb120f142d 100644 --- a/indra/newview/llsurface.h +++ b/indra/newview/llsurface.h @@ -168,9 +168,6 @@ public: F32 mDetailTextureScale; // Number of times to repeat detail texture across this surface - static F32 sTextureUpdateTime; - static S32 sTexelsUpdated; - protected: void createSTexture(); void createWaterTexture(); diff --git a/indra/newview/lltexturefetch.cpp b/indra/newview/lltexturefetch.cpp index 143db79eb5..001060f4de 100755 --- a/indra/newview/lltexturefetch.cpp +++ b/indra/newview/lltexturefetch.cpp @@ -3242,7 +3242,7 @@ void LLTextureFetchDebugger::startDebug() } //collect statistics - mTotalFetchingTime = gDebugTimers[0].getElapsedTimeF32() - mTotalFetchingTime; + mTotalFetchingTime = gTextureTimer.getElapsedTimeF32() - mTotalFetchingTime; std::set fetched_textures; S32 size = mFetchingHistory.size(); @@ -3324,7 +3324,7 @@ void LLTextureFetchDebugger::stopDebug() //unlock the fetcher mFetcher->lockFetcher(false); mFreezeHistory = FALSE; - mTotalFetchingTime = gDebugTimers[0].getElapsedTimeF32(); //reset + mTotalFetchingTime = gTextureTimer.getElapsedTimeF32(); //reset } //called in the main thread and when the fetching queue is empty @@ -3637,7 +3637,7 @@ bool LLTextureFetchDebugger::update() case REFETCH_VIS_CACHE: if (LLAppViewer::getTextureFetch()->getNumRequests() == 0) { - mRefetchVisCacheTime = gDebugTimers[0].getElapsedTimeF32() - mTotalFetchingTime; + mRefetchVisCacheTime = gTextureTimer.getElapsedTimeF32() - mTotalFetchingTime; mState = IDLE; mFetcher->lockFetcher(true); } @@ -3645,7 +3645,7 @@ bool LLTextureFetchDebugger::update() case REFETCH_VIS_HTTP: if (LLAppViewer::getTextureFetch()->getNumRequests() == 0) { - mRefetchVisHTTPTime = gDebugTimers[0].getElapsedTimeF32() - mTotalFetchingTime; + mRefetchVisHTTPTime = gTextureTimer.getElapsedTimeF32() - mTotalFetchingTime; mState = IDLE; mFetcher->lockFetcher(true); } diff --git a/indra/newview/llviewermenu.cpp b/indra/newview/llviewermenu.cpp index 34e916fec0..75b4815ba7 100644 --- a/indra/newview/llviewermenu.cpp +++ b/indra/newview/llviewermenu.cpp @@ -1314,22 +1314,6 @@ class LLAdvancedPrintAgentInfo : public view_listener_t } }; - - -//////////////////////////////// -// PRINT TEXTURE MEMORY STATS // -//////////////////////////////// - - -class LLAdvancedPrintTextureMemoryStats : public view_listener_t -{ - bool handleEvent(const LLSD& userdata) - { - output_statistics(NULL); - return true; - } -}; - ////////////////// // DEBUG CLICKS // ////////////////// @@ -8280,7 +8264,6 @@ void initialize_menus() commit.add("Advanced.DumpFocusHolder", boost::bind(&handle_dump_focus) ); view_listener_t::addMenu(new LLAdvancedPrintSelectedObjectInfo(), "Advanced.PrintSelectedObjectInfo"); view_listener_t::addMenu(new LLAdvancedPrintAgentInfo(), "Advanced.PrintAgentInfo"); - view_listener_t::addMenu(new LLAdvancedPrintTextureMemoryStats(), "Advanced.PrintTextureMemoryStats"); view_listener_t::addMenu(new LLAdvancedToggleDebugClicks(), "Advanced.ToggleDebugClicks"); view_listener_t::addMenu(new LLAdvancedCheckDebugClicks(), "Advanced.CheckDebugClicks"); view_listener_t::addMenu(new LLAdvancedCheckDebugViews(), "Advanced.CheckDebugViews"); diff --git a/indra/newview/llviewerstats.cpp b/indra/newview/llviewerstats.cpp index c1ccfe3faa..fe78b1232c 100644 --- a/indra/newview/llviewerstats.cpp +++ b/indra/newview/llviewerstats.cpp @@ -286,19 +286,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(); } @@ -401,140 +401,6 @@ void LLViewerStats::addToMessage(LLSD &body) const // *NOTE:Mani The following methods used to exist in viewer.cpp // Moving them here, but not merging them into LLViewerStats yet. -void reset_statistics() -{ - if (LLSurface::sTextureUpdateTime) - { - LLSurface::sTexelsUpdated = 0; - LLSurface::sTextureUpdateTime = 0.f; - } -} - - -void output_statistics(void*) -{ - llinfos << "Number of orphans: " << gObjectList.getOrphanCount() << llendl; - llinfos << "Number of dead objects: " << gObjectList.mNumDeadObjects << llendl; - llinfos << "Num images: " << gTextureList.getNumImages() << llendl; - llinfos << "Texture usage: " << LLImageGL::sGlobalTextureMemoryInBytes << llendl; - llinfos << "Texture working set: " << LLImageGL::sBoundTextureMemoryInBytes << llendl; - llinfos << "Raw usage: " << LLImageRaw::sGlobalRawMemory << llendl; - llinfos << "Formatted usage: " << LLImageFormatted::sGlobalFormattedMemory << llendl; - llinfos << "Zombie Viewer Objects: " << LLViewerObject::getNumZombieObjects() << llendl; - llinfos << "Number of lights: " << gPipeline.getLightCount() << llendl; - - llinfos << "Memory Usage:" << llendl; - llinfos << "--------------------------------" << llendl; - llinfos << "Pipeline:" << llendl; - llinfos << llendl; - -#if LL_SMARTHEAP - llinfos << "--------------------------------" << llendl; - { - llinfos << "sizeof(LLVOVolume) = " << sizeof(LLVOVolume) << llendl; - - U32 total_pool_size = 0; - U32 total_used_size = 0; - MEM_POOL_INFO pool_info; - MEM_POOL_STATUS pool_status; - U32 pool_num = 0; - for(pool_status = MemPoolFirst( &pool_info, 1 ); - pool_status != MEM_POOL_END; - pool_status = MemPoolNext( &pool_info, 1 ) ) - { - llinfos << "Pool #" << pool_num << llendl; - if( MEM_POOL_OK != pool_status ) - { - llwarns << "Pool not ok" << llendl; - continue; - } - - llinfos << "Pool blockSizeFS " << pool_info.blockSizeFS - << " pageSize " << pool_info.pageSize - << llendl; - - U32 pool_count = MemPoolCount(pool_info.pool); - llinfos << "Blocks " << pool_count << llendl; - - U32 pool_size = MemPoolSize( pool_info.pool ); - if( pool_size == MEM_ERROR_RET ) - { - llinfos << "MemPoolSize() failed (" << pool_num << ")" << llendl; - } - else - { - llinfos << "MemPool Size " << pool_size / 1024 << "K" << llendl; - } - - total_pool_size += pool_size; - - if( !MemPoolLock( pool_info.pool ) ) - { - llinfos << "MemPoolLock failed (" << pool_num << ") " << llendl; - continue; - } - - U32 used_size = 0; - MEM_POOL_ENTRY entry; - entry.entry = NULL; - while( MemPoolWalk( pool_info.pool, &entry ) == MEM_POOL_OK ) - { - if( entry.isInUse ) - { - used_size += entry.size; - } - } - - MemPoolUnlock( pool_info.pool ); - - llinfos << "MemPool Used " << used_size/1024 << "K" << llendl; - total_used_size += used_size; - pool_num++; - } - - llinfos << "Total Pool Size " << total_pool_size/1024 << "K" << llendl; - llinfos << "Total Used Size " << total_used_size/1024 << "K" << llendl; - - } -#endif - - llinfos << "--------------------------------" << llendl; - llinfos << "Avatar Memory (partly overlaps with above stats):" << llendl; - LLTexLayerStaticImageList::getInstance()->dumpByteCount(); - LLVOAvatarSelf::dumpScratchTextureByteCount(); - LLTexLayerSetBuffer::dumpTotalByteCount(); - LLVOAvatarSelf::dumpTotalLocalTextureByteCount(); - LLTexLayerParamAlpha::dumpCacheByteCount(); - LLVOAvatar::dumpBakedStatus(); - - llinfos << llendl; - - llinfos << "Object counts:" << llendl; - S32 i; - S32 obj_counts[256]; -// S32 app_angles[256]; - for (i = 0; i < 256; i++) - { - obj_counts[i] = 0; - } - for (i = 0; i < gObjectList.getNumObjects(); i++) - { - LLViewerObject *objectp = gObjectList.getObject(i); - if (objectp) - { - obj_counts[objectp->getPCode()]++; - } - } - for (i = 0; i < 256; i++) - { - if (obj_counts[i]) - { - llinfos << LLPrimitive::pCodeToString(i) << ":" << obj_counts[i] << llendl; - } - } -} - - U32 gTotalLandIn = 0, gTotalLandOut = 0; U32 gTotalWaterIn = 0, gTotalWaterOut = 0; @@ -552,16 +418,9 @@ U32 gTotalTextureBytesPerBoostLevel[LLViewerTexture::MAX_GL_IMAGE_CATEGORY] extern U32 gVisCompared; extern U32 gVisTested; -std::map gDebugTimers; -std::map gDebugTimerLabel; +extern 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; @@ -588,11 +447,7 @@ void update_statistics(U32 frame_count) 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 - stats.setStat(LLViewerStats::ST_SHADER_OBJECTS, (F64)gSavedSettings.getS32("VertexShaderLevelObject")); - stats.setStat(LLViewerStats::ST_SHADER_AVATAR, (F64)gSavedSettings.getBOOL("VertexShaderLevelAvatar")); - stats.setStat(LLViewerStats::ST_SHADER_ENVIRONMENT, (F64)gSavedSettings.getBOOL("VertexShaderLevelEnvironment")); -#endif + stats.setStat(LLViewerStats::ST_FRAME_SECS, gDebugView->mFastTimerView->getTime("Frame")); F64 idle_secs = gDebugView->mFastTimerView->getTime("Idle"); F64 network_secs = gDebugView->mFastTimerView->getTime("Network"); @@ -624,11 +479,11 @@ void update_statistics(U32 frame_count) if (LLAppViewer::getTextureFetch()->getNumRequests() == 0) { - gDebugTimers[0].pause(); + gTextureTimer.pause(); } else { - gDebugTimers[0].unpause(); + gTextureTimer.unpause(); } { @@ -664,7 +519,6 @@ void update_statistics(U32 frame_count) texture_stats_timer.reset(); } } - } class ViewerStatsResponder : public LLHTTPClient::Responder @@ -824,10 +678,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 @@ -918,13 +769,6 @@ LLSD LLViewerStats::PhaseMap::dumpPhases() 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; } diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h index 9a2a33fa7b..0402b82154 100644 --- a/indra/newview/llviewerstats.h +++ b/indra/newview/llviewerstats.h @@ -33,82 +33,82 @@ 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 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; // Simulator stats - LLStat mSimTimeDilation; - - LLStat mSimFPS; - LLStat mSimPhysicsFPS; - LLStat mSimAgentUPS; - LLStat mSimScriptEPS; - - LLStat mSimFrameMsec; - LLStat mSimNetMsec; - LLStat mSimSimOtherMsec; - LLStat mSimSimPhysicsMsec; - - LLStat mSimSimPhysicsStepMsec; - LLStat mSimSimPhysicsShapeUpdateMsec; - LLStat mSimSimPhysicsOtherMsec; - - LLStat mSimAgentMsec; - LLStat mSimImagesMsec; - LLStat mSimScriptMsec; - LLStat mSimSpareMsec; - LLStat mSimSleepMsec; - LLStat mSimPumpIOMsec; - - LLStat mSimMainAgents; - LLStat mSimChildAgents; - LLStat mSimObjects; - LLStat mSimActiveObjects; - LLStat mSimActiveScripts; - - LLStat mSimInPPS; - LLStat mSimOutPPS; - LLStat mSimPendingDownloads; - LLStat mSimPendingUploads; - LLStat mSimPendingLocalUploads; - LLStat mSimTotalUnackedBytes; - - LLStat mPhysicsPinnedTasks; - LLStat mPhysicsLODTasks; - LLStat mPhysicsMemoryAllocated; - - LLStat mSimPingStat; - - LLStat mNumImagesStat; - LLStat mNumRawImagesStat; - LLStat mGLTexMemStat; - LLStat mGLBoundMemStat; - LLStat mRawMemStat; - LLStat mFormattedMemStat; - - LLStat mNumObjectsStat; - LLStat mNumActiveObjectsStat; - LLStat mNumNewObjectsStat; - LLStat mNumSizeCulledStat; - LLStat mNumVisCulledStat; + LLStat mSimTimeDilation, + + mSimFPS, + mSimPhysicsFPS, + mSimAgentUPS, + mSimScriptEPS, + + mSimFrameMsec, + mSimNetMsec, + mSimSimOtherMsec, + mSimSimPhysicsMsec, + + mSimSimPhysicsStepMsec, + mSimSimPhysicsShapeUpdateMsec, + mSimSimPhysicsOtherMsec, + + mSimAgentMsec, + mSimImagesMsec, + mSimScriptMsec, + mSimSpareMsec, + mSimSleepMsec, + mSimPumpIOMsec, + + mSimMainAgents, + mSimChildAgents, + mSimObjects, + mSimActiveObjects, + mSimActiveScripts, + + mSimInPPS, + mSimOutPPS, + mSimPendingDownloads, + mSimPendingUploads, + mSimPendingLocalUploads, + mSimTotalUnackedBytes, + + mPhysicsPinnedTasks, + mPhysicsLODTasks, + mPhysicsMemoryAllocated, + + mSimPingStat, + + mNumImagesStat, + mNumRawImagesStat, + mGLTexMemStat, + mGLBoundMemStat, + mRawMemStat, + mFormattedMemStat, + + mNumObjectsStat, + mNumActiveObjectsStat, + mNumNewObjectsStat, + mNumSizeCulledStat, + mNumVisCulledStat; void resetStats(); public: @@ -177,7 +177,6 @@ public: ST_COUNT = 58 }; - LLViewerStats(); ~LLViewerStats(); @@ -304,14 +303,10 @@ 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/llviewertexturelist.cpp b/indra/newview/llviewertexturelist.cpp index 528e0080b7..9e1e92f8e8 100644 --- a/indra/newview/llviewertexturelist.cpp +++ b/indra/newview/llviewertexturelist.cpp @@ -906,14 +906,6 @@ F32 LLViewerTextureList::updateImagesFetchTextures(F32 max_time) } min_count--; } - //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 39e330ad66..9e9b41d3c8 100755 --- a/indra/newview/llviewerwindow.cpp +++ b/indra/newview/llviewerwindow.cpp @@ -333,19 +333,13 @@ public: if (gSavedSettings.getBOOL("DebugShowTime")) { 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; - 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; - } + 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)); + addText(xpos, ypos, llformat(" "Texture": %d:%02d:%02d", hours,mins,secs)); ypos += y_inc2; + F32 time = gFrameTimeSeconds; S32 hours = (S32)(time / (60*60)); diff --git a/indra/newview/llvlcomposition.cpp b/indra/newview/llvlcomposition.cpp index ec932501e5..abb5153480 100644 --- a/indra/newview/llvlcomposition.cpp +++ b/indra/newview/llvlcomposition.cpp @@ -457,8 +457,6 @@ BOOL LLVLComposition::generateTexture(const F32 x, const F32 y, texturep->createGLTexture(0, raw); } texturep->setSubImage(raw, tex_x_begin, tex_y_begin, tex_x_end - tex_x_begin, tex_y_end - tex_y_begin); - LLSurface::sTextureUpdateTime += gen_timer.getElapsedTimeF32(); - LLSurface::sTexelsUpdated += (tex_x_end - tex_x_begin) * (tex_y_end - tex_y_begin); for (S32 i = 0; i < 4; i++) { -- cgit v1.3 From a98c7e150b3404cbbb7324bfe2a5f547f613346b Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 6 Aug 2012 16:08:04 -0700 Subject: llfasttimer cleanup removed unnecessary cache miss from fast timers renamed llfasttimer_class back to llfasttimer --- indra/llcommon/CMakeLists.txt | 3 +- indra/llcommon/llfasttimer.cpp | 661 +++++++++++++++++++++++++ indra/llcommon/llfasttimer.h | 362 +++++++++++++- indra/llcommon/llfasttimer_class.cpp | 913 ----------------------------------- indra/llcommon/llfasttimer_class.h | 258 ---------- indra/newview/llappviewer.cpp | 7 +- indra/newview/llappviewer.h | 3 + indra/newview/lldrawpoolbump.cpp | 2 +- indra/newview/llfasttimerview.cpp | 28 +- indra/newview/llfasttimerview.h | 1 + 10 files changed, 1046 insertions(+), 1192 deletions(-) create mode 100644 indra/llcommon/llfasttimer.cpp delete mode 100644 indra/llcommon/llfasttimer_class.cpp delete mode 100644 indra/llcommon/llfasttimer_class.h (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/llcommon/CMakeLists.txt b/indra/llcommon/CMakeLists.txt index dd7b8c6eb8..7795d55d62 100644 --- a/indra/llcommon/CMakeLists.txt +++ b/indra/llcommon/CMakeLists.txt @@ -53,7 +53,7 @@ set(llcommon_SOURCE_FILES lleventfilter.cpp llevents.cpp lleventtimer.cpp - llfasttimer_class.cpp + llfasttimer.cpp llfile.cpp llfindlocale.cpp llfixedbuffer.cpp @@ -167,7 +167,6 @@ set(llcommon_HEADER_FILES lleventemitter.h llextendedstatus.h llfasttimer.h - llfasttimer_class.h llfile.h llfindlocale.h llfixedbuffer.h diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp new file mode 100644 index 0000000000..ff6806082c --- /dev/null +++ b/indra/llcommon/llfasttimer.cpp @@ -0,0 +1,661 @@ +/** + * @file llfasttimer.cpp + * @brief Implementation of the fast timer. + * + * $LicenseInfo:firstyear=2004&license=viewerlgpl$ + * Second Life Viewer Source Code + * Copyright (C) 2010, Linden Research, Inc. + * + * This library is free software; you can redistribute it and/or + * modify it under the terms of the GNU Lesser General Public + * License as published by the Free Software Foundation; + * version 2.1 of the License only. + * + * This library is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + * Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public + * License along with this library; if not, write to the Free Software + * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA + * + * Linden Research, Inc., 945 Battery Street, San Francisco, CA 94111 USA + * $/LicenseInfo$ + */ +#include "linden_common.h" + +#include "llfasttimer.h" + +#include "llmemory.h" +#include "llprocessor.h" +#include "llsingleton.h" +#include "lltreeiterators.h" +#include "llsdserialize.h" + +#include + + +#if LL_WINDOWS +#include "lltimer.h" +#elif LL_LINUX || LL_SOLARIS +#include +#include +#include "lltimer.h" +#elif LL_DARWIN +#include +#include "lltimer.h" // get_clock_count() +#else +#error "architecture not supported" +#endif + +////////////////////////////////////////////////////////////////////////////// +// statics + +S32 LLFastTimer::sCurFrameIndex = -1; +S32 LLFastTimer::sLastFrameIndex = -1; +U64 LLFastTimer::sLastFrameTime = LLFastTimer::getCPUClockCount64(); +bool LLFastTimer::sPauseHistory = 0; +bool LLFastTimer::sResetHistory = 0; +LLFastTimer::CurTimerData LLFastTimer::sCurTimerData; +BOOL LLFastTimer::sLog = FALSE; +std::string LLFastTimer::sLogName = ""; +BOOL LLFastTimer::sMetricLog = FALSE; +LLMutex* LLFastTimer::sLogLock = NULL; +std::queue LLFastTimer::sLogQueue; + +#if LL_LINUX || LL_SOLARIS +U64 LLFastTimer::sClockResolution = 1000000000; // Nanosecond resolution +#else +U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution +#endif + +// FIXME: move these declarations to the relevant modules + +// helper functions +typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; + +static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::NamedTimer& id) +{ + return timer_tree_bottom_up_iterator_t(&id, + boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); +} + +static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() +{ + return timer_tree_bottom_up_iterator_t(); +} + +typedef LLTreeDFSIter timer_tree_dfs_iterator_t; + + +static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::NamedTimer& id) +{ + return timer_tree_dfs_iterator_t(&id, + boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), + boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); +} + +static timer_tree_dfs_iterator_t end_timer_tree() +{ + return timer_tree_dfs_iterator_t(); +} + +// factory class that creates NamedTimers via static DeclareTimer objects +class NamedTimerFactory : public LLSingleton +{ +public: + NamedTimerFactory() + : mTimerRoot(NULL) + {} + + /*virtual */ void initSingleton() + { + mTimerRoot = new LLFastTimer::NamedTimer("root"); + mRootFrameState.setNamedTimer(mTimerRoot); + mTimerRoot->setFrameState(&mRootFrameState); + mTimerRoot->mParent = mTimerRoot; + mRootFrameState.mParent = &mRootFrameState; + } + + ~NamedTimerFactory() + { + std::for_each(mTimers.begin(), mTimers.end(), DeletePairedPointer()); + + delete mTimerRoot; + } + + LLFastTimer::NamedTimer& createNamedTimer(const std::string& name, LLFastTimer::FrameState* state) + { + timer_map_t::iterator found_it = mTimers.find(name); + if (found_it != mTimers.end()) + { + llerrs << "Duplicate timer declaration for: " << name << llendl; + return *found_it->second; + } + + LLFastTimer::NamedTimer* timer = new LLFastTimer::NamedTimer(name); + timer->setFrameState(state); + timer->setParent(mTimerRoot); + mTimers.insert(std::make_pair(name, timer)); + + return *timer; + } + + LLFastTimer::NamedTimer* getTimerByName(const std::string& name) + { + timer_map_t::iterator found_it = mTimers.find(name); + if (found_it != mTimers.end()) + { + return found_it->second; + } + return NULL; + } + + LLFastTimer::NamedTimer* getRootTimer() { return mTimerRoot; } + + typedef std::map timer_map_t; + timer_map_t::iterator beginTimers() { return mTimers.begin(); } + timer_map_t::iterator endTimers() { return mTimers.end(); } + S32 timerCount() { return mTimers.size(); } + +private: + timer_map_t mTimers; + + LLFastTimer::NamedTimer* mTimerRoot; + LLFastTimer::FrameState mRootFrameState; +}; + +LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open ) +: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) +{ + mTimer.setCollapsed(!open); +} + +LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name) +: mTimer(NamedTimerFactory::instance().createNamedTimer(name, &mFrameState)) +{ +} + +//static +#if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) +U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +{ + return sClockResolution >> 8; +} +#else // windows or x86-mac or x86-linux or x86-solaris +U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer +{ +#if LL_FASTTIMER_USE_RDTSC || !LL_WINDOWS + //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz + static U64 sCPUClockFrequency = U64(LLProcessorInfo().getCPUFrequency()*1000000.0); + + // we drop the low-order byte in our timers, so report a lower frequency +#else + // If we're not using RDTSC, each fasttimer tick is just a performance counter tick. + // Not redefining the clock frequency itself (in llprocessor.cpp/calculate_cpu_frequency()) + // since that would change displayed MHz stats for CPUs + static bool firstcall = true; + static U64 sCPUClockFrequency; + if (firstcall) + { + QueryPerformanceFrequency((LARGE_INTEGER*)&sCPUClockFrequency); + firstcall = false; + } +#endif + return sCPUClockFrequency >> 8; +} +#endif + +LLFastTimer::FrameState::FrameState() +: mActiveCount(0), + mCalls(0), + mSelfTimeCounter(0), + mParent(NULL), + mLastCaller(NULL), + mMoveUpTree(false) +{} + + +LLFastTimer::NamedTimer::NamedTimer(const std::string& name) +: mName(name), + mCollapsed(true), + mParent(NULL), + mTotalTimeCounter(0), + mCountAverage(0), + mCallAverage(0), + mNeedsSorting(false), + mFrameState(NULL) +{ + mCountHistory = new U32[HISTORY_NUM]; + memset(mCountHistory, 0, sizeof(U32) * HISTORY_NUM); + mCallHistory = new U32[HISTORY_NUM]; + memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); +} + +LLFastTimer::NamedTimer::~NamedTimer() +{ + delete[] mCountHistory; + delete[] mCallHistory; +} + +std::string LLFastTimer::NamedTimer::getToolTip(S32 history_idx) +{ + F64 ms_multiplier = 1000.0 / (F64)LLFastTimer::countsPerSecond(); + if (history_idx < 0) + { + // by default, show average number of call + return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getCountAverage() * ms_multiplier), (S32)getCallAverage()); + } + else + { + return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getHistoricalCount(history_idx) * ms_multiplier), (S32)getHistoricalCalls(history_idx)); + } +} + +void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) +{ + llassert_always(parent != this); + llassert_always(parent != NULL); + + if (mParent) + { + // subtract our accumulated from previous parent + for (S32 i = 0; i < HISTORY_NUM; i++) + { + mParent->mCountHistory[i] -= mCountHistory[i]; + } + + // subtract average timing from previous parent + mParent->mCountAverage -= mCountAverage; + + std::vector& children = mParent->getChildren(); + std::vector::iterator found_it = std::find(children.begin(), children.end(), this); + if (found_it != children.end()) + { + children.erase(found_it); + } + } + + mParent = parent; + if (parent) + { + getFrameState().mParent = &parent->getFrameState(); + parent->getChildren().push_back(this); + parent->mNeedsSorting = true; + } +} + +S32 LLFastTimer::NamedTimer::getDepth() +{ + S32 depth = 0; + NamedTimer* timerp = mParent; + while(timerp) + { + depth++; + timerp = timerp->mParent; + } + return depth; +} + +// static +void LLFastTimer::NamedTimer::processTimes() +{ + if (sCurFrameIndex < 0) return; + + buildHierarchy(); + accumulateTimings(); +} + +// sort child timers by name +struct SortTimerByName +{ + bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2) + { + return i1->getName() < i2->getName(); + } +}; + +//static +void LLFastTimer::NamedTimer::buildHierarchy() +{ + if (sCurFrameIndex < 0 ) return; + + // set up initial tree + { + for (instance_iter it = beginInstances(); it != endInstances(); ++it) + { + NamedTimer& timer = *it; + if (&timer == NamedTimerFactory::instance().getRootTimer()) continue; + + // bootstrap tree construction by attaching to last timer to be on stack + // when this timer was called + if (timer.getFrameState().mLastCaller && timer.mParent == NamedTimerFactory::instance().getRootTimer()) + { + timer.setParent(timer.getFrameState().mLastCaller->mTimer); + // no need to push up tree on first use, flag can be set spuriously + timer.getFrameState().mMoveUpTree = false; + } + } + } + + // bump timers up tree if they've been flagged as being in the wrong place + // do this in a bottom up order to promote descendants first before promoting ancestors + // this preserves partial order derived from current frame's observations + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getRootTimer()); + it != end_timer_tree_bottom_up(); + ++it) + { + NamedTimer* timerp = *it; + // skip root timer + if (timerp == NamedTimerFactory::instance().getRootTimer()) continue; + + if (timerp->getFrameState().mMoveUpTree) + { + // since ancestors have already been visited, reparenting won't affect tree traversal + //step up tree, bringing our descendants with us + LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << + " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; + timerp->setParent(timerp->getParent()->getParent()); + timerp->getFrameState().mMoveUpTree = false; + + // don't bubble up any ancestors until descendants are done bubbling up + it.skipAncestors(); + } + } + + // sort timers by time last called, so call graph makes sense + for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); + it != end_timer_tree(); + ++it) + { + NamedTimer* timerp = (*it); + if (timerp->mNeedsSorting) + { + std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); + } + timerp->mNeedsSorting = false; + } +} + +//static +void LLFastTimer::NamedTimer::accumulateTimings() +{ + U32 cur_time = getCPUClockCount32(); + + // walk up stack of active timers and accumulate current time while leaving timing structures active + LLFastTimer* cur_timer = sCurTimerData.mCurTimer; + // root defined by parent pointing to self + CurTimerData* cur_data = &sCurTimerData; + while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) + { + U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; + U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; + cur_data->mChildTime = 0; + cur_timer->mFrameState->mSelfTimeCounter += self_time_delta; + cur_timer->mStartTime = cur_time; + + cur_data = &cur_timer->mLastTimerData; + cur_data->mChildTime += cumulative_time_delta; + + cur_timer = cur_timer->mLastTimerData.mCurTimer; + } + + // traverse tree in DFS post order, or bottom up + for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getRootTimer()); + it != end_timer_tree_bottom_up(); + ++it) + { + NamedTimer* timerp = (*it); + timerp->mTotalTimeCounter = timerp->getFrameState().mSelfTimeCounter; + for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) + { + timerp->mTotalTimeCounter += (*child_it)->mTotalTimeCounter; + } + + S32 cur_frame = sCurFrameIndex; + if (cur_frame >= 0) + { + // update timer history + int hidx = cur_frame % HISTORY_NUM; + + timerp->mCountHistory[hidx] = timerp->mTotalTimeCounter; + timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTotalTimeCounter) / (cur_frame+1); + timerp->mCallHistory[hidx] = timerp->getFrameState().mCalls; + timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->getFrameState().mCalls) / (cur_frame+1); + } + } +} + +// static +void LLFastTimer::NamedTimer::resetFrame() +{ + if (sLog) + { //output current frame counts to performance log + + static S32 call_count = 0; + if (call_count % 100 == 0) + { + LL_DEBUGS("FastTimers") << "countsPerSecond (32 bit): " << countsPerSecond() << LL_ENDL; + LL_DEBUGS("FastTimers") << "get_clock_count (64 bit): " << get_clock_count() << llendl; + LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; + LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; + LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64())/((F64)LLProcessorInfo().getCPUFrequency()*1000000.0) << LL_ENDL; + } + call_count++; + + F64 iclock_freq = 1000.0 / countsPerSecond(); // good place to calculate clock frequency + + F64 total_time = 0; + LLSD sd; + + { + for (instance_iter it = beginInstances(); it != endInstances(); ++it) + { + NamedTimer& timer = *it; + FrameState& info = timer.getFrameState(); + sd[timer.getName()]["Time"] = (LLSD::Real) (info.mSelfTimeCounter*iclock_freq); + sd[timer.getName()]["Calls"] = (LLSD::Integer) info.mCalls; + + // computing total time here because getting the root timer's getCountHistory + // doesn't work correctly on the first frame + total_time = total_time + info.mSelfTimeCounter * iclock_freq; + } + } + + sd["Total"]["Time"] = (LLSD::Real) total_time; + sd["Total"]["Calls"] = (LLSD::Integer) 1; + + { + LLMutexLock lock(sLogLock); + sLogQueue.push(sd); + } + } + + // reset for next frame + for (instance_iter it = beginInstances(); it != endInstances(); ++it) + { + NamedTimer& timer = *it; + + FrameState& info = timer.getFrameState(); + info.mSelfTimeCounter = 0; + info.mCalls = 0; + info.mLastCaller = NULL; + info.mMoveUpTree = false; + // update parent pointer in timer state struct + if (timer.mParent) + { + info.mParent = &timer.mParent->getFrameState(); + } + } +} + +//static +void LLFastTimer::NamedTimer::reset() +{ + resetFrame(); // reset frame data + + // walk up stack of active timers and reset start times to current time + // effectively zeroing out any accumulated time + U32 cur_time = getCPUClockCount32(); + + // root defined by parent pointing to self + CurTimerData* cur_data = &sCurTimerData; + LLFastTimer* cur_timer = cur_data->mCurTimer; + while(cur_timer && cur_timer->mLastTimerData.mCurTimer != cur_timer) + { + cur_timer->mStartTime = cur_time; + cur_data->mChildTime = 0; + + cur_data = &cur_timer->mLastTimerData; + cur_timer = cur_data->mCurTimer; + } + + // reset all history + { + for (instance_iter it = beginInstances(); it != endInstances(); ++it) + { + NamedTimer& timer = *it; + if (&timer != NamedTimerFactory::instance().getRootTimer()) + { + timer.setParent(NamedTimerFactory::instance().getRootTimer()); + } + + timer.mCountAverage = 0; + timer.mCallAverage = 0; + memset(timer.mCountHistory, 0, sizeof(U32) * HISTORY_NUM); + memset(timer.mCallHistory, 0, sizeof(U32) * HISTORY_NUM); + } + } + + sLastFrameIndex = 0; + sCurFrameIndex = 0; +} + +U32 LLFastTimer::NamedTimer::getHistoricalCount(S32 history_index) const +{ + S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; + return mCountHistory[history_idx]; +} + +U32 LLFastTimer::NamedTimer::getHistoricalCalls(S32 history_index ) const +{ + S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; + return mCallHistory[history_idx]; +} + +LLFastTimer::FrameState& LLFastTimer::NamedTimer::getFrameState() const +{ + return *mFrameState; +} + +std::vector::const_iterator LLFastTimer::NamedTimer::beginChildren() +{ + return mChildren.begin(); +} + +std::vector::const_iterator LLFastTimer::NamedTimer::endChildren() +{ + return mChildren.end(); +} + +std::vector& LLFastTimer::NamedTimer::getChildren() +{ + return mChildren; +} + +//static +void LLFastTimer::nextFrame() +{ + countsPerSecond(); // good place to calculate clock frequency + U64 frame_time = getCPUClockCount64(); + if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) + { + llinfos << "Slow frame, fast timers inaccurate" << llendl; + } + + if (!sPauseHistory) + { + NamedTimer::processTimes(); + sLastFrameIndex = sCurFrameIndex++; + } + + // get ready for next frame + NamedTimer::resetFrame(); + sLastFrameTime = frame_time; +} + +//static +void LLFastTimer::dumpCurTimes() +{ + // accumulate timings, etc. + NamedTimer::processTimes(); + + F64 clock_freq = (F64)countsPerSecond(); + F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds + + // walk over timers in depth order and output timings + for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); + it != end_timer_tree(); + ++it) + { + NamedTimer* timerp = (*it); + F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); + // Don't bother with really brief times, keep output concise + if (total_time_ms < 0.1) continue; + + std::ostringstream out_str; + for (S32 i = 0; i < timerp->getDepth(); i++) + { + out_str << "\t"; + } + + + out_str << timerp->getName() << " " + << std::setprecision(3) << total_time_ms << " ms, " + << timerp->getHistoricalCalls(0) << " calls"; + + llinfos << out_str.str() << llendl; + } +} + +//static +void LLFastTimer::reset() +{ + NamedTimer::reset(); +} + + +//static +void LLFastTimer::writeLog(std::ostream& os) +{ + while (!sLogQueue.empty()) + { + LLSD& sd = sLogQueue.front(); + LLSDSerialize::toXML(sd, os); + LLMutexLock lock(sLogLock); + sLogQueue.pop(); + } +} + +//static +const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& name) +{ + return NamedTimerFactory::instance().getTimerByName(name); +} + +LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) +: mFrameState(state) +{ + U32 start_time = getCPUClockCount32(); + mStartTime = start_time; + mFrameState->mActiveCount++; + LLFastTimer::sCurTimerData.mCurTimer = this; + LLFastTimer::sCurTimerData.mFrameState = mFrameState; + LLFastTimer::sCurTimerData.mChildTime = 0; + mLastTimerData = LLFastTimer::sCurTimerData; +} + + diff --git a/indra/llcommon/llfasttimer.h b/indra/llcommon/llfasttimer.h index 2b25f2fabb..e42e549df5 100644 --- a/indra/llcommon/llfasttimer.h +++ b/indra/llcommon/llfasttimer.h @@ -1,6 +1,6 @@ /** * @file llfasttimer.h - * @brief Inline implementations of fast timers. + * @brief Declaration of a fast timer. * * $LicenseInfo:firstyear=2004&license=viewerlgpl$ * Second Life Viewer Source Code @@ -27,9 +27,363 @@ #ifndef LL_FASTTIMER_H #define LL_FASTTIMER_H -// Implementation of getCPUClockCount32() and getCPUClockCount64 are now in llfastertimer_class.cpp. +#include "llinstancetracker.h" -// pull in the actual class definition -#include "llfasttimer_class.h" +#define FAST_TIMER_ON 1 +#define DEBUG_FAST_TIMER_THREADS 1 + +class LLMutex; + +#include +#include "llsd.h" + +#define LL_FASTTIMER_USE_RDTSC 1 + + +LL_COMMON_API void assert_main_thread(); + +class LL_COMMON_API LLFastTimer +{ +public: + class NamedTimer; + + struct LL_COMMON_API FrameState + { + FrameState(); + void setNamedTimer(NamedTimer* timerp) { mTimer = timerp; } + + U32 mSelfTimeCounter; + U32 mCalls; + FrameState* mParent; // info for caller timer + FrameState* mLastCaller; // used to bootstrap tree construction + NamedTimer* mTimer; + U16 mActiveCount; // number of timers with this ID active on stack + bool mMoveUpTree; // needs to be moved up the tree of timers at the end of frame + }; + + // stores a "named" timer instance to be reused via multiple LLFastTimer stack instances + class LL_COMMON_API NamedTimer + : public LLInstanceTracker + { + friend class DeclareTimer; + public: + ~NamedTimer(); + + enum { HISTORY_NUM = 300 }; + + const std::string& getName() const { return mName; } + NamedTimer* getParent() const { return mParent; } + void setParent(NamedTimer* parent); + S32 getDepth(); + std::string getToolTip(S32 history_index = -1); + + typedef std::vector::const_iterator child_const_iter; + child_const_iter beginChildren(); + child_const_iter endChildren(); + std::vector& getChildren(); + + void setCollapsed(bool collapsed) { mCollapsed = collapsed; } + bool getCollapsed() const { return mCollapsed; } + + U32 getCountAverage() const { return mCountAverage; } + U32 getCallAverage() const { return mCallAverage; } + + U32 getHistoricalCount(S32 history_index = 0) const; + U32 getHistoricalCalls(S32 history_index = 0) const; + + void setFrameState(FrameState* state) { mFrameState = state; state->setNamedTimer(this); } + FrameState& getFrameState() const; + + private: + friend class LLFastTimer; + friend class NamedTimerFactory; + + // + // methods + // + NamedTimer(const std::string& name); + // recursive call to gather total time from children + static void accumulateTimings(); + + // updates cumulative times and hierarchy, + // can be called multiple times in a frame, at any point + static void processTimes(); + + static void buildHierarchy(); + static void resetFrame(); + static void reset(); + + // + // members + // + FrameState* mFrameState; + + std::string mName; + + U32 mTotalTimeCounter; + + U32 mCountAverage; + U32 mCallAverage; + + U32* mCountHistory; + U32* mCallHistory; + + // tree structure + NamedTimer* mParent; // NamedTimer of caller(parent) + std::vector mChildren; + bool mCollapsed; // don't show children + bool mNeedsSorting; // sort children whenever child added + }; + + // used to statically declare a new named timer + class LL_COMMON_API DeclareTimer + : public LLInstanceTracker + { + friend class LLFastTimer; + public: + DeclareTimer(const std::string& name, bool open); + DeclareTimer(const std::string& name); + + NamedTimer& getNamedTimer() { return mTimer; } + + private: + FrameState mFrameState; + NamedTimer& mTimer; + }; + +public: + LLFastTimer(LLFastTimer::FrameState* state); + + LL_FORCE_INLINE LLFastTimer(LLFastTimer::DeclareTimer& timer) + : mFrameState(&timer.mFrameState) + { +#if FAST_TIMER_ON + LLFastTimer::FrameState* frame_state = mFrameState; + mStartTime = getCPUClockCount32(); + + frame_state->mActiveCount++; + frame_state->mCalls++; + // keep current parent as long as it is active when we are + frame_state->mMoveUpTree |= (frame_state->mParent->mActiveCount == 0); + + LLFastTimer::CurTimerData* cur_timer_data = &LLFastTimer::sCurTimerData; + mLastTimerData = *cur_timer_data; + cur_timer_data->mCurTimer = this; + cur_timer_data->mFrameState = frame_state; + cur_timer_data->mChildTime = 0; +#endif +#if DEBUG_FAST_TIMER_THREADS +#if !LL_RELEASE + assert_main_thread(); +#endif +#endif + } + + LL_FORCE_INLINE ~LLFastTimer() + { +#if FAST_TIMER_ON + LLFastTimer::FrameState* frame_state = mFrameState; + U32 total_time = getCPUClockCount32() - mStartTime; + + frame_state->mSelfTimeCounter += total_time - LLFastTimer::sCurTimerData.mChildTime; + frame_state->mActiveCount--; + + // store last caller to bootstrap tree creation + // do this in the destructor in case of recursion to get topmost caller + frame_state->mLastCaller = mLastTimerData.mFrameState; + + // we are only tracking self time, so subtract our total time delta from parents + mLastTimerData.mChildTime += total_time; + + LLFastTimer::sCurTimerData = mLastTimerData; +#endif + } + +public: + static LLMutex* sLogLock; + static std::queue sLogQueue; + static BOOL sLog; + static BOOL sMetricLog; + static std::string sLogName; + static bool sPauseHistory; + static bool sResetHistory; + + // call this once a frame to reset timers + static void nextFrame(); + + // dumps current cumulative frame stats to log + // call nextFrame() to reset timers + static void dumpCurTimes(); + + // call this to reset timer hierarchy, averages, etc. + static void reset(); + + static U64 countsPerSecond(); + static S32 getLastFrameIndex() { return sLastFrameIndex; } + static S32 getCurFrameIndex() { return sCurFrameIndex; } + + static void writeLog(std::ostream& os); + static const NamedTimer* getTimerByName(const std::string& name); + + struct CurTimerData + { + LLFastTimer* mCurTimer; + FrameState* mFrameState; + U32 mChildTime; + }; + static CurTimerData sCurTimerData; + +private: + + + ////////////////////////////////////////////////////////////////////////////// + // + // Important note: These implementations must be FAST! + // + + +#if LL_WINDOWS + // + // Windows implementation of CPU clock + // + + // + // NOTE: put back in when we aren't using platform sdk anymore + // + // because MS has different signatures for these functions in winnt.h + // need to rename them to avoid conflicts + //#define _interlockedbittestandset _renamed_interlockedbittestandset + //#define _interlockedbittestandreset _renamed_interlockedbittestandreset + //#include + //#undef _interlockedbittestandset + //#undef _interlockedbittestandreset + + //inline U32 LLFastTimer::getCPUClockCount32() + //{ + // U64 time_stamp = __rdtsc(); + // return (U32)(time_stamp >> 8); + //} + // + //// return full timer value, *not* shifted by 8 bits + //inline U64 LLFastTimer::getCPUClockCount64() + //{ + // return __rdtsc(); + //} + + // shift off lower 8 bits for lower resolution but longer term timing + // on 1Ghz machine, a 32-bit word will hold ~1000 seconds of timing +#if LL_FASTTIMER_USE_RDTSC + static U32 getCPUClockCount32() + { + U32 ret_val; + __asm + { + _emit 0x0f + _emit 0x31 + shr eax,8 + shl edx,24 + or eax, edx + mov dword ptr [ret_val], eax + } + return ret_val; + } + + // return full timer value, *not* shifted by 8 bits + static U64 getCPUClockCount64() + { + U64 ret_val; + __asm + { + _emit 0x0f + _emit 0x31 + mov eax,eax + mov edx,edx + mov dword ptr [ret_val+4], edx + mov dword ptr [ret_val], eax + } + return ret_val; + } + +#else + //LL_COMMON_API U64 get_clock_count(); // in lltimer.cpp + // These use QueryPerformanceCounter, which is arguably fine and also works on AMD architectures. + static U32 getCPUClockCount32() + { + return (U32)(get_clock_count()>>8); + } + + static U64 getCPUClockCount64() + { + return get_clock_count(); + } + +#endif + +#endif + + +#if (LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) + // + // Linux and Solaris implementation of CPU clock - non-x86. + // This is accurate but SLOW! Only use out of desperation. + // + // Try to use the MONOTONIC clock if available, this is a constant time counter + // with nanosecond resolution (but not necessarily accuracy) and attempts are + // made to synchronize this value between cores at kernel start. It should not + // be affected by CPU frequency. If not available use the REALTIME clock, but + // this may be affected by NTP adjustments or other user activity affecting + // the system time. + static U64 getCPUClockCount64() + { + struct timespec tp; + +#ifdef CLOCK_MONOTONIC // MONOTONIC supported at build-time? + if (-1 == clock_gettime(CLOCK_MONOTONIC,&tp)) // if MONOTONIC isn't supported at runtime then ouch, try REALTIME +#endif + clock_gettime(CLOCK_REALTIME,&tp); + + return (tp.tv_sec*sClockResolution)+tp.tv_nsec; + } + + static U32 getCPUClockCount32() + { + return (U32)(getCPUClockCount64() >> 8); + } + +#endif // (LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) + + +#if (LL_LINUX || LL_SOLARIS || LL_DARWIN) && (defined(__i386__) || defined(__amd64__)) + // + // Mac+Linux+Solaris FAST x86 implementation of CPU clock + static U32 getCPUClockCount32() + { + U64 x; + __asm__ volatile (".byte 0x0f, 0x31": "=A"(x)); + return (U32)(x >> 8); + } + + static U64 getCPUClockCount64() + { + U64 x; + __asm__ volatile (".byte 0x0f, 0x31": "=A"(x)); + return x; + } + +#endif + + static U64 sClockResolution; + + static S32 sCurFrameIndex; + static S32 sLastFrameIndex; + static U64 sLastFrameTime; + + U32 mStartTime; + LLFastTimer::FrameState* mFrameState; + LLFastTimer::CurTimerData mLastTimerData; + +}; + +typedef class LLFastTimer LLFastTimer; #endif // LL_LLFASTTIMER_H diff --git a/indra/llcommon/llfasttimer_class.cpp b/indra/llcommon/llfasttimer_class.cpp deleted file mode 100644 index 449074dbfe..0000000000 --- a/indra/llcommon/llfasttimer_class.cpp +++ /dev/null @@ -1,913 +0,0 @@ -/** - * @file llfasttimer_class.cpp - * @brief Implementation of the fast timer. - * - * $LicenseInfo:firstyear=2004&license=viewerlgpl$ - * Second Life Viewer Source Code - * Copyright (C) 2010, Linden Research, Inc. - * - * This library is free software; you can redistribute it and/or - * modify it under the terms of the GNU Lesser General Public - * License as published by the Free Software Foundation; - * version 2.1 of the License only. - * - * This library is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU - * Lesser General Public License for more details. - * - * You should have received a copy of the GNU Lesser General Public - * License along with this library; if not, write to the Free Software - * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA - * - * Linden Research, Inc., 945 Battery Street, San Francisco, CA 94111 USA - * $/LicenseInfo$ - */ -#include "linden_common.h" - -#include "llfasttimer.h" - -#include "llmemory.h" -#include "llprocessor.h" -#include "llsingleton.h" -#include "lltreeiterators.h" -#include "llsdserialize.h" - -#include - - -#if LL_WINDOWS -#include "lltimer.h" -#elif LL_LINUX || LL_SOLARIS -#include -#include -#include "lltimer.h" -#elif LL_DARWIN -#include -#include "lltimer.h" // get_clock_count() -#else -#error "architecture not supported" -#endif - -////////////////////////////////////////////////////////////////////////////// -// statics - -S32 LLFastTimer::sCurFrameIndex = -1; -S32 LLFastTimer::sLastFrameIndex = -1; -U64 LLFastTimer::sLastFrameTime = LLFastTimer::getCPUClockCount64(); -bool LLFastTimer::sPauseHistory = 0; -bool LLFastTimer::sResetHistory = 0; -LLFastTimer::CurTimerData LLFastTimer::sCurTimerData; -BOOL LLFastTimer::sLog = FALSE; -std::string LLFastTimer::sLogName = ""; -BOOL LLFastTimer::sMetricLog = FALSE; -LLMutex* LLFastTimer::sLogLock = NULL; -std::queue LLFastTimer::sLogQueue; - -#define USE_RDTSC 0 - -#if LL_LINUX || LL_SOLARIS -U64 LLFastTimer::sClockResolution = 1000000000; // Nanosecond resolution -#else -U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution -#endif - -std::vector* LLFastTimer::sTimerInfos = NULL; - -// FIXME: move these declarations to the relevant modules - -// helper functions -typedef LLTreeDFSPostIter timer_tree_bottom_up_iterator_t; - -static timer_tree_bottom_up_iterator_t begin_timer_tree_bottom_up(LLFastTimer::NamedTimer& id) -{ - return timer_tree_bottom_up_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); -} - -static timer_tree_bottom_up_iterator_t end_timer_tree_bottom_up() -{ - return timer_tree_bottom_up_iterator_t(); -} - -typedef LLTreeDFSIter timer_tree_dfs_iterator_t; - - -static timer_tree_dfs_iterator_t begin_timer_tree(LLFastTimer::NamedTimer& id) -{ - return timer_tree_dfs_iterator_t(&id, - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::beginChildren), _1), - boost::bind(boost::mem_fn(&LLFastTimer::NamedTimer::endChildren), _1)); -} - -static timer_tree_dfs_iterator_t end_timer_tree() -{ - return timer_tree_dfs_iterator_t(); -} - - - -// factory class that creates NamedTimers via static DeclareTimer objects -class NamedTimerFactory : public LLSingleton -{ -public: - NamedTimerFactory() - : mActiveTimerRoot(NULL), - mTimerRoot(NULL), - mAppTimer(NULL), - mRootFrameState(NULL) - {} - - /*virtual */ void initSingleton() - { - mTimerRoot = new LLFastTimer::NamedTimer("root"); - - mActiveTimerRoot = new LLFastTimer::NamedTimer("Frame"); - mActiveTimerRoot->setCollapsed(false); - - mRootFrameState = new LLFastTimer::FrameState(mActiveTimerRoot); - mRootFrameState->mParent = &mTimerRoot->getFrameState(); - mActiveTimerRoot->setParent(mTimerRoot); - - mAppTimer = new LLFastTimer(mRootFrameState); - } - - ~NamedTimerFactory() - { - std::for_each(mTimers.begin(), mTimers.end(), DeletePairedPointer()); - - delete mAppTimer; - delete mActiveTimerRoot; - delete mTimerRoot; - delete mRootFrameState; - } - - LLFastTimer::NamedTimer& createNamedTimer(const std::string& name) - { - timer_map_t::iterator found_it = mTimers.find(name); - if (found_it != mTimers.end()) - { - return *found_it->second; - } - - LLFastTimer::NamedTimer* timer = new LLFastTimer::NamedTimer(name); - timer->setParent(mTimerRoot); - mTimers.insert(std::make_pair(name, timer)); - - return *timer; - } - - LLFastTimer::NamedTimer* getTimerByName(const std::string& name) - { - timer_map_t::iterator found_it = mTimers.find(name); - if (found_it != mTimers.end()) - { - return found_it->second; - } - return NULL; - } - - LLFastTimer::NamedTimer* getActiveRootTimer() { return mActiveTimerRoot; } - LLFastTimer::NamedTimer* getRootTimer() { return mTimerRoot; } - const LLFastTimer* getAppTimer() { return mAppTimer; } - LLFastTimer::FrameState& getRootFrameState() { return *mRootFrameState; } - - typedef std::map timer_map_t; - timer_map_t::iterator beginTimers() { return mTimers.begin(); } - timer_map_t::iterator endTimers() { return mTimers.end(); } - S32 timerCount() { return mTimers.size(); } - -private: - timer_map_t mTimers; - - LLFastTimer::NamedTimer* mActiveTimerRoot; - LLFastTimer::NamedTimer* mTimerRoot; - LLFastTimer* mAppTimer; - LLFastTimer::FrameState* mRootFrameState; -}; - -void update_cached_pointers_if_changed() -{ - // detect when elements have moved and update cached pointers - static LLFastTimer::FrameState* sFirstTimerAddress = NULL; - if (&*(LLFastTimer::getFrameStateList().begin()) != sFirstTimerAddress) - { - LLFastTimer::DeclareTimer::updateCachedPointers(); - } - sFirstTimerAddress = &*(LLFastTimer::getFrameStateList().begin()); -} - -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name, bool open ) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name)) -{ - mTimer.setCollapsed(!open); - mFrameState = &mTimer.getFrameState(); - update_cached_pointers_if_changed(); -} - -LLFastTimer::DeclareTimer::DeclareTimer(const std::string& name) -: mTimer(NamedTimerFactory::instance().createNamedTimer(name)) -{ - mFrameState = &mTimer.getFrameState(); - update_cached_pointers_if_changed(); -} - -// static -void LLFastTimer::DeclareTimer::updateCachedPointers() -{ - // propagate frame state pointers to timer declarations - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - // update cached pointer - it->mFrameState = &it->mTimer.getFrameState(); - } - - // also update frame states of timers on stack - LLFastTimer* cur_timerp = LLFastTimer::sCurTimerData.mCurTimer; - while(cur_timerp->mLastTimerData.mCurTimer != cur_timerp) - { - cur_timerp->mFrameState = &cur_timerp->mFrameState->mTimer->getFrameState(); - cur_timerp = cur_timerp->mLastTimerData.mCurTimer; - } -} - -//static -#if (LL_DARWIN || LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer -{ - return sClockResolution >> 8; -} -#else // windows or x86-mac or x86-linux or x86-solaris -U64 LLFastTimer::countsPerSecond() // counts per second for the *32-bit* timer -{ -#if USE_RDTSC || !LL_WINDOWS - //getCPUFrequency returns MHz and sCPUClockFrequency wants to be in Hz - static U64 sCPUClockFrequency = U64(LLProcessorInfo().getCPUFrequency()*1000000.0); - - // we drop the low-order byte in our timers, so report a lower frequency -#else - // If we're not using RDTSC, each fasttimer tick is just a performance counter tick. - // Not redefining the clock frequency itself (in llprocessor.cpp/calculate_cpu_frequency()) - // since that would change displayed MHz stats for CPUs - static bool firstcall = true; - static U64 sCPUClockFrequency; - if (firstcall) - { - QueryPerformanceFrequency((LARGE_INTEGER*)&sCPUClockFrequency); - firstcall = false; - } -#endif - return sCPUClockFrequency >> 8; -} -#endif - -LLFastTimer::FrameState::FrameState(LLFastTimer::NamedTimer* timerp) -: mActiveCount(0), - mCalls(0), - mSelfTimeCounter(0), - mParent(NULL), - mLastCaller(NULL), - mMoveUpTree(false), - mTimer(timerp) -{} - - -LLFastTimer::NamedTimer::NamedTimer(const std::string& name) -: mName(name), - mCollapsed(true), - mParent(NULL), - mTotalTimeCounter(0), - mCountAverage(0), - mCallAverage(0), - mNeedsSorting(false) -{ - info_list_t& frame_state_list = getFrameStateList(); - mFrameStateIndex = frame_state_list.size(); - getFrameStateList().push_back(FrameState(this)); - - mCountHistory = new U32[HISTORY_NUM]; - memset(mCountHistory, 0, sizeof(U32) * HISTORY_NUM); - mCallHistory = new U32[HISTORY_NUM]; - memset(mCallHistory, 0, sizeof(U32) * HISTORY_NUM); -} - -LLFastTimer::NamedTimer::~NamedTimer() -{ - delete[] mCountHistory; - delete[] mCallHistory; -} - -std::string LLFastTimer::NamedTimer::getToolTip(S32 history_idx) -{ - F64 ms_multiplier = 1000.0 / (F64)LLFastTimer::countsPerSecond(); - if (history_idx < 0) - { - // by default, show average number of call - return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getCountAverage() * ms_multiplier), (S32)getCallAverage()); - } - else - { - return llformat("%s (%d ms, %d calls)", getName().c_str(), (S32)(getHistoricalCount(history_idx) * ms_multiplier), (S32)getHistoricalCalls(history_idx)); - } -} - -void LLFastTimer::NamedTimer::setParent(NamedTimer* parent) -{ - llassert_always(parent != this); - llassert_always(parent != NULL); - - if (mParent) - { - // subtract our accumulated from previous parent - for (S32 i = 0; i < HISTORY_NUM; i++) - { - mParent->mCountHistory[i] -= mCountHistory[i]; - } - - // subtract average timing from previous parent - mParent->mCountAverage -= mCountAverage; - - std::vector& children = mParent->getChildren(); - std::vector::iterator found_it = std::find(children.begin(), children.end(), this); - if (found_it != children.end()) - { - children.erase(found_it); - } - } - - mParent = parent; - if (parent) - { - getFrameState().mParent = &parent->getFrameState(); - parent->getChildren().push_back(this); - parent->mNeedsSorting = true; - } -} - -S32 LLFastTimer::NamedTimer::getDepth() -{ - S32 depth = 0; - NamedTimer* timerp = mParent; - while(timerp) - { - depth++; - timerp = timerp->mParent; - } - return depth; -} - -// static -void LLFastTimer::NamedTimer::processTimes() -{ - if (sCurFrameIndex < 0) return; - - buildHierarchy(); - accumulateTimings(); -} - -// sort timer info structs by depth first traversal order -struct SortTimersDFS -{ - bool operator()(const LLFastTimer::FrameState& i1, const LLFastTimer::FrameState& i2) - { - return i1.mTimer->getFrameStateIndex() < i2.mTimer->getFrameStateIndex(); - } -}; - -// sort child timers by name -struct SortTimerByName -{ - bool operator()(const LLFastTimer::NamedTimer* i1, const LLFastTimer::NamedTimer* i2) - { - return i1->getName() < i2->getName(); - } -}; - -//static -void LLFastTimer::NamedTimer::buildHierarchy() -{ - if (sCurFrameIndex < 0 ) return; - - // set up initial tree - { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - NamedTimer& timer = *it; - if (&timer == NamedTimerFactory::instance().getRootTimer()) continue; - - // bootstrap tree construction by attaching to last timer to be on stack - // when this timer was called - if (timer.getFrameState().mLastCaller && timer.mParent == NamedTimerFactory::instance().getRootTimer()) - { - timer.setParent(timer.getFrameState().mLastCaller->mTimer); - // no need to push up tree on first use, flag can be set spuriously - timer.getFrameState().mMoveUpTree = false; - } - } - } - - // bump timers up tree if they've been flagged as being in the wrong place - // do this in a bottom up order to promote descendants first before promoting ancestors - // this preserves partial order derived from current frame's observations - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree_bottom_up(); - ++it) - { - NamedTimer* timerp = *it; - // skip root timer - if (timerp == NamedTimerFactory::instance().getRootTimer()) continue; - - if (timerp->getFrameState().mMoveUpTree) - { - // since ancestors have already been visited, reparenting won't affect tree traversal - //step up tree, bringing our descendants with us - LL_DEBUGS("FastTimers") << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() << - " to child of " << timerp->getParent()->getParent()->getName() << LL_ENDL; - timerp->setParent(timerp->getParent()->getParent()); - timerp->getFrameState().mMoveUpTree = false; - - // don't bubble up any ancestors until descendants are done bubbling up - it.skipAncestors(); - } - } - - // sort timers by time last called, so call graph makes sense - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree(); - ++it) - { - NamedTimer* timerp = (*it); - if (timerp->mNeedsSorting) - { - std::sort(timerp->getChildren().begin(), timerp->getChildren().end(), SortTimerByName()); - } - timerp->mNeedsSorting = false; - } -} - -//static -void LLFastTimer::NamedTimer::accumulateTimings() -{ - U32 cur_time = getCPUClockCount32(); - - // walk up stack of active timers and accumulate current time while leaving timing structures active - LLFastTimer* cur_timer = sCurTimerData.mCurTimer; - // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; - while(cur_timer->mLastTimerData.mCurTimer != cur_timer) - { - U32 cumulative_time_delta = cur_time - cur_timer->mStartTime; - U32 self_time_delta = cumulative_time_delta - cur_data->mChildTime; - cur_data->mChildTime = 0; - cur_timer->mFrameState->mSelfTimeCounter += self_time_delta; - cur_timer->mStartTime = cur_time; - - cur_data = &cur_timer->mLastTimerData; - cur_data->mChildTime += cumulative_time_delta; - - cur_timer = cur_timer->mLastTimerData.mCurTimer; - } - - // traverse tree in DFS post order, or bottom up - for(timer_tree_bottom_up_iterator_t it = begin_timer_tree_bottom_up(*NamedTimerFactory::instance().getActiveRootTimer()); - it != end_timer_tree_bottom_up(); - ++it) - { - NamedTimer* timerp = (*it); - timerp->mTotalTimeCounter = timerp->getFrameState().mSelfTimeCounter; - for (child_const_iter child_it = timerp->beginChildren(); child_it != timerp->endChildren(); ++child_it) - { - timerp->mTotalTimeCounter += (*child_it)->mTotalTimeCounter; - } - - S32 cur_frame = sCurFrameIndex; - if (cur_frame >= 0) - { - // update timer history - int hidx = cur_frame % HISTORY_NUM; - - timerp->mCountHistory[hidx] = timerp->mTotalTimeCounter; - timerp->mCountAverage = ((U64)timerp->mCountAverage * cur_frame + timerp->mTotalTimeCounter) / (cur_frame+1); - timerp->mCallHistory[hidx] = timerp->getFrameState().mCalls; - timerp->mCallAverage = ((U64)timerp->mCallAverage * cur_frame + timerp->getFrameState().mCalls) / (cur_frame+1); - } - } -} - -// static -void LLFastTimer::NamedTimer::resetFrame() -{ - if (sLog) - { //output current frame counts to performance log - - static S32 call_count = 0; - if (call_count % 100 == 0) - { - LL_DEBUGS("FastTimers") << "countsPerSecond (32 bit): " << countsPerSecond() << LL_ENDL; - LL_DEBUGS("FastTimers") << "get_clock_count (64 bit): " << get_clock_count() << llendl; - LL_DEBUGS("FastTimers") << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount32() " << getCPUClockCount32() << LL_ENDL; - LL_DEBUGS("FastTimers") << "getCPUClockCount64() " << getCPUClockCount64() << LL_ENDL; - LL_DEBUGS("FastTimers") << "elapsed sec " << ((F64)getCPUClockCount64())/((F64)LLProcessorInfo().getCPUFrequency()*1000000.0) << LL_ENDL; - } - call_count++; - - F64 iclock_freq = 1000.0 / countsPerSecond(); // good place to calculate clock frequency - - F64 total_time = 0; - LLSD sd; - - { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - NamedTimer& timer = *it; - FrameState& info = timer.getFrameState(); - sd[timer.getName()]["Time"] = (LLSD::Real) (info.mSelfTimeCounter*iclock_freq); - sd[timer.getName()]["Calls"] = (LLSD::Integer) info.mCalls; - - // computing total time here because getting the root timer's getCountHistory - // doesn't work correctly on the first frame - total_time = total_time + info.mSelfTimeCounter * iclock_freq; - } - } - - sd["Total"]["Time"] = (LLSD::Real) total_time; - sd["Total"]["Calls"] = (LLSD::Integer) 1; - - { - LLMutexLock lock(sLogLock); - sLogQueue.push(sd); - } - } - - - // tag timers by position in depth first traversal of tree - S32 index = 0; - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree(); - ++it) - { - NamedTimer* timerp = (*it); - - timerp->mFrameStateIndex = index; - index++; - - llassert_always(timerp->mFrameStateIndex < (S32)getFrameStateList().size()); - } - - // sort timers by DFS traversal order to improve cache coherency - std::sort(getFrameStateList().begin(), getFrameStateList().end(), SortTimersDFS()); - - // update pointers into framestatelist now that we've sorted it - DeclareTimer::updateCachedPointers(); - - // reset for next frame - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - NamedTimer& timer = *it; - - FrameState& info = timer.getFrameState(); - info.mSelfTimeCounter = 0; - info.mCalls = 0; - info.mLastCaller = NULL; - info.mMoveUpTree = false; - // update parent pointer in timer state struct - if (timer.mParent) - { - info.mParent = &timer.mParent->getFrameState(); - } - } -} - -//static -void LLFastTimer::NamedTimer::reset() -{ - resetFrame(); // reset frame data - - // walk up stack of active timers and reset start times to current time - // effectively zeroing out any accumulated time - U32 cur_time = getCPUClockCount32(); - - // root defined by parent pointing to self - CurTimerData* cur_data = &sCurTimerData; - LLFastTimer* cur_timer = cur_data->mCurTimer; - while(cur_timer->mLastTimerData.mCurTimer != cur_timer) - { - cur_timer->mStartTime = cur_time; - cur_data->mChildTime = 0; - - cur_data = &cur_timer->mLastTimerData; - cur_timer = cur_data->mCurTimer; - } - - // reset all history - { - for (instance_iter it = beginInstances(); it != endInstances(); ++it) - { - NamedTimer& timer = *it; - if (&timer != NamedTimerFactory::instance().getRootTimer()) - { - timer.setParent(NamedTimerFactory::instance().getRootTimer()); - } - - timer.mCountAverage = 0; - timer.mCallAverage = 0; - memset(timer.mCountHistory, 0, sizeof(U32) * HISTORY_NUM); - memset(timer.mCallHistory, 0, sizeof(U32) * HISTORY_NUM); - } - } - - sLastFrameIndex = 0; - sCurFrameIndex = 0; -} - -//static -LLFastTimer::info_list_t& LLFastTimer::getFrameStateList() -{ - if (!sTimerInfos) - { - sTimerInfos = new info_list_t(); - } - return *sTimerInfos; -} - - -U32 LLFastTimer::NamedTimer::getHistoricalCount(S32 history_index) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; - return mCountHistory[history_idx]; -} - -U32 LLFastTimer::NamedTimer::getHistoricalCalls(S32 history_index ) const -{ - S32 history_idx = (getLastFrameIndex() + history_index) % LLFastTimer::NamedTimer::HISTORY_NUM; - return mCallHistory[history_idx]; -} - -LLFastTimer::FrameState& LLFastTimer::NamedTimer::getFrameState() const -{ - llassert_always(mFrameStateIndex >= 0); - if (this == NamedTimerFactory::instance().getActiveRootTimer()) - { - return NamedTimerFactory::instance().getRootFrameState(); - } - return getFrameStateList()[mFrameStateIndex]; -} - -// static -LLFastTimer::NamedTimer& LLFastTimer::NamedTimer::getRootNamedTimer() -{ - return *NamedTimerFactory::instance().getActiveRootTimer(); -} - -std::vector::const_iterator LLFastTimer::NamedTimer::beginChildren() -{ - return mChildren.begin(); -} - -std::vector::const_iterator LLFastTimer::NamedTimer::endChildren() -{ - return mChildren.end(); -} - -std::vector& LLFastTimer::NamedTimer::getChildren() -{ - return mChildren; -} - -//static -void LLFastTimer::nextFrame() -{ - countsPerSecond(); // good place to calculate clock frequency - U64 frame_time = getCPUClockCount64(); - if ((frame_time - sLastFrameTime) >> 8 > 0xffffffff) - { - llinfos << "Slow frame, fast timers inaccurate" << llendl; - } - - if (!sPauseHistory) - { - NamedTimer::processTimes(); - sLastFrameIndex = sCurFrameIndex++; - } - - // get ready for next frame - NamedTimer::resetFrame(); - sLastFrameTime = frame_time; -} - -//static -void LLFastTimer::dumpCurTimes() -{ - // accumulate timings, etc. - NamedTimer::processTimes(); - - F64 clock_freq = (F64)countsPerSecond(); - F64 iclock_freq = 1000.0 / clock_freq; // clock_ticks -> milliseconds - - // walk over timers in depth order and output timings - for(timer_tree_dfs_iterator_t it = begin_timer_tree(*NamedTimerFactory::instance().getRootTimer()); - it != end_timer_tree(); - ++it) - { - NamedTimer* timerp = (*it); - F64 total_time_ms = ((F64)timerp->getHistoricalCount(0) * iclock_freq); - // Don't bother with really brief times, keep output concise - if (total_time_ms < 0.1) continue; - - std::ostringstream out_str; - for (S32 i = 0; i < timerp->getDepth(); i++) - { - out_str << "\t"; - } - - - out_str << timerp->getName() << " " - << std::setprecision(3) << total_time_ms << " ms, " - << timerp->getHistoricalCalls(0) << " calls"; - - llinfos << out_str.str() << llendl; - } -} - -//static -void LLFastTimer::reset() -{ - NamedTimer::reset(); -} - - -//static -void LLFastTimer::writeLog(std::ostream& os) -{ - while (!sLogQueue.empty()) - { - LLSD& sd = sLogQueue.front(); - LLSDSerialize::toXML(sd, os); - LLMutexLock lock(sLogLock); - sLogQueue.pop(); - } -} - -//static -const LLFastTimer::NamedTimer* LLFastTimer::getTimerByName(const std::string& name) -{ - return NamedTimerFactory::instance().getTimerByName(name); -} - -LLFastTimer::LLFastTimer(LLFastTimer::FrameState* state) -: mFrameState(state) -{ - U32 start_time = getCPUClockCount32(); - mStartTime = start_time; - mFrameState->mActiveCount++; - LLFastTimer::sCurTimerData.mCurTimer = this; - LLFastTimer::sCurTimerData.mFrameState = mFrameState; - LLFastTimer::sCurTimerData.mChildTime = 0; - mLastTimerData = LLFastTimer::sCurTimerData; -} - - -////////////////////////////////////////////////////////////////////////////// -// -// Important note: These implementations must be FAST! -// - - -#if LL_WINDOWS -// -// Windows implementation of CPU clock -// - -// -// NOTE: put back in when we aren't using platform sdk anymore -// -// because MS has different signatures for these functions in winnt.h -// need to rename them to avoid conflicts -//#define _interlockedbittestandset _renamed_interlockedbittestandset -//#define _interlockedbittestandreset _renamed_interlockedbittestandreset -//#include -//#undef _interlockedbittestandset -//#undef _interlockedbittestandreset - -//inline U32 LLFastTimer::getCPUClockCount32() -//{ -// U64 time_stamp = __rdtsc(); -// return (U32)(time_stamp >> 8); -//} -// -//// return full timer value, *not* shifted by 8 bits -//inline U64 LLFastTimer::getCPUClockCount64() -//{ -// return __rdtsc(); -//} - -// shift off lower 8 bits for lower resolution but longer term timing -// on 1Ghz machine, a 32-bit word will hold ~1000 seconds of timing -#if USE_RDTSC -U32 LLFastTimer::getCPUClockCount32() -{ - U32 ret_val; - __asm - { - _emit 0x0f - _emit 0x31 - shr eax,8 - shl edx,24 - or eax, edx - mov dword ptr [ret_val], eax - } - return ret_val; -} - -// return full timer value, *not* shifted by 8 bits -U64 LLFastTimer::getCPUClockCount64() -{ - U64 ret_val; - __asm - { - _emit 0x0f - _emit 0x31 - mov eax,eax - mov edx,edx - mov dword ptr [ret_val+4], edx - mov dword ptr [ret_val], eax - } - return ret_val; -} - -std::string LLFastTimer::sClockType = "rdtsc"; - -#else -//LL_COMMON_API U64 get_clock_count(); // in lltimer.cpp -// These use QueryPerformanceCounter, which is arguably fine and also works on AMD architectures. -U32 LLFastTimer::getCPUClockCount32() -{ - return (U32)(get_clock_count()>>8); -} - -U64 LLFastTimer::getCPUClockCount64() -{ - return get_clock_count(); -} - -std::string LLFastTimer::sClockType = "QueryPerformanceCounter"; -#endif - -#endif - - -#if (LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) -// -// Linux and Solaris implementation of CPU clock - non-x86. -// This is accurate but SLOW! Only use out of desperation. -// -// Try to use the MONOTONIC clock if available, this is a constant time counter -// with nanosecond resolution (but not necessarily accuracy) and attempts are -// made to synchronize this value between cores at kernel start. It should not -// be affected by CPU frequency. If not available use the REALTIME clock, but -// this may be affected by NTP adjustments or other user activity affecting -// the system time. -U64 LLFastTimer::getCPUClockCount64() -{ - struct timespec tp; - -#ifdef CLOCK_MONOTONIC // MONOTONIC supported at build-time? - if (-1 == clock_gettime(CLOCK_MONOTONIC,&tp)) // if MONOTONIC isn't supported at runtime then ouch, try REALTIME -#endif - clock_gettime(CLOCK_REALTIME,&tp); - - return (tp.tv_sec*LLFastTimer::sClockResolution)+tp.tv_nsec; -} - -U32 LLFastTimer::getCPUClockCount32() -{ - return (U32)(LLFastTimer::getCPUClockCount64() >> 8); -} - -std::string LLFastTimer::sClockType = "clock_gettime"; - -#endif // (LL_LINUX || LL_SOLARIS) && !(defined(__i386__) || defined(__amd64__)) - - -#if (LL_LINUX || LL_SOLARIS || LL_DARWIN) && (defined(__i386__) || defined(__amd64__)) -// -// Mac+Linux+Solaris FAST x86 implementation of CPU clock -U32 LLFastTimer::getCPUClockCount32() -{ - U64 x; - __asm__ volatile (".byte 0x0f, 0x31": "=A"(x)); - return (U32)(x >> 8); -} - -U64 LLFastTimer::getCPUClockCount64() -{ - U64 x; - __asm__ volatile (".byte 0x0f, 0x31": "=A"(x)); - return x; -} - -std::string LLFastTimer::sClockType = "rdtsc"; -#endif - diff --git a/indra/llcommon/llfasttimer_class.h b/indra/llcommon/llfasttimer_class.h deleted file mode 100644 index 8a12aa1372..0000000000 --- a/indra/llcommon/llfasttimer_class.h +++ /dev/null @@ -1,258 +0,0 @@ -/** - * @file llfasttimer_class.h - * @brief Declaration of a fast timer. - * - * $LicenseInfo:firstyear=2004&license=viewerlgpl$ - * Second Life Viewer Source Code - * Copyright (C) 2010, Linden Research, Inc. - * - * This library is free software; you can redistribute it and/or - * modify it under the terms of the GNU Lesser General Public - * License as published by the Free Software Foundation; - * version 2.1 of the License only. - * - * This library is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU - * Lesser General Public License for more details. - * - * You should have received a copy of the GNU Lesser General Public - * License along with this library; if not, write to the Free Software - * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA - * - * Linden Research, Inc., 945 Battery Street, San Francisco, CA 94111 USA - * $/LicenseInfo$ - */ - -#ifndef LL_FASTTIMER_CLASS_H -#define LL_FASTTIMER_CLASS_H - -#include "llinstancetracker.h" - -#define FAST_TIMER_ON 1 -#define DEBUG_FAST_TIMER_THREADS 1 - -class LLMutex; - -#include -#include "llsd.h" - -LL_COMMON_API void assert_main_thread(); - -class LL_COMMON_API LLFastTimer -{ -public: - class NamedTimer; - - struct LL_COMMON_API FrameState - { - FrameState(NamedTimer* timerp); - - U32 mSelfTimeCounter; - U32 mCalls; - FrameState* mParent; // info for caller timer - FrameState* mLastCaller; // used to bootstrap tree construction - NamedTimer* mTimer; - U16 mActiveCount; // number of timers with this ID active on stack - bool mMoveUpTree; // needs to be moved up the tree of timers at the end of frame - }; - - // stores a "named" timer instance to be reused via multiple LLFastTimer stack instances - class LL_COMMON_API NamedTimer - : public LLInstanceTracker - { - friend class DeclareTimer; - public: - ~NamedTimer(); - - enum { HISTORY_NUM = 300 }; - - const std::string& getName() const { return mName; } - NamedTimer* getParent() const { return mParent; } - void setParent(NamedTimer* parent); - S32 getDepth(); - std::string getToolTip(S32 history_index = -1); - - typedef std::vector::const_iterator child_const_iter; - child_const_iter beginChildren(); - child_const_iter endChildren(); - std::vector& getChildren(); - - void setCollapsed(bool collapsed) { mCollapsed = collapsed; } - bool getCollapsed() const { return mCollapsed; } - - U32 getCountAverage() const { return mCountAverage; } - U32 getCallAverage() const { return mCallAverage; } - - U32 getHistoricalCount(S32 history_index = 0) const; - U32 getHistoricalCalls(S32 history_index = 0) const; - - static NamedTimer& getRootNamedTimer(); - - S32 getFrameStateIndex() const { return mFrameStateIndex; } - - FrameState& getFrameState() const; - - private: - friend class LLFastTimer; - friend class NamedTimerFactory; - - // - // methods - // - NamedTimer(const std::string& name); - // recursive call to gather total time from children - static void accumulateTimings(); - - // updates cumulative times and hierarchy, - // can be called multiple times in a frame, at any point - static void processTimes(); - - static void buildHierarchy(); - static void resetFrame(); - static void reset(); - - // - // members - // - S32 mFrameStateIndex; - - std::string mName; - - U32 mTotalTimeCounter; - - U32 mCountAverage; - U32 mCallAverage; - - U32* mCountHistory; - U32* mCallHistory; - - // tree structure - NamedTimer* mParent; // NamedTimer of caller(parent) - std::vector mChildren; - bool mCollapsed; // don't show children - bool mNeedsSorting; // sort children whenever child added - }; - - // used to statically declare a new named timer - class LL_COMMON_API DeclareTimer - : public LLInstanceTracker - { - friend class LLFastTimer; - public: - DeclareTimer(const std::string& name, bool open); - DeclareTimer(const std::string& name); - - static void updateCachedPointers(); - - private: - NamedTimer& mTimer; - FrameState* mFrameState; - }; - -public: - LLFastTimer(LLFastTimer::FrameState* state); - - LL_FORCE_INLINE LLFastTimer(LLFastTimer::DeclareTimer& timer) - : mFrameState(timer.mFrameState) - { -#if FAST_TIMER_ON - LLFastTimer::FrameState* frame_state = mFrameState; - mStartTime = getCPUClockCount32(); - - frame_state->mActiveCount++; - frame_state->mCalls++; - // keep current parent as long as it is active when we are - frame_state->mMoveUpTree |= (frame_state->mParent->mActiveCount == 0); - - LLFastTimer::CurTimerData* cur_timer_data = &LLFastTimer::sCurTimerData; - mLastTimerData = *cur_timer_data; - cur_timer_data->mCurTimer = this; - cur_timer_data->mFrameState = frame_state; - cur_timer_data->mChildTime = 0; -#endif -#if DEBUG_FAST_TIMER_THREADS -#if !LL_RELEASE - assert_main_thread(); -#endif -#endif - } - - LL_FORCE_INLINE ~LLFastTimer() - { -#if FAST_TIMER_ON - LLFastTimer::FrameState* frame_state = mFrameState; - U32 total_time = getCPUClockCount32() - mStartTime; - - frame_state->mSelfTimeCounter += total_time - LLFastTimer::sCurTimerData.mChildTime; - frame_state->mActiveCount--; - - // store last caller to bootstrap tree creation - // do this in the destructor in case of recursion to get topmost caller - frame_state->mLastCaller = mLastTimerData.mFrameState; - - // we are only tracking self time, so subtract our total time delta from parents - mLastTimerData.mChildTime += total_time; - - LLFastTimer::sCurTimerData = mLastTimerData; -#endif - } - -public: - static LLMutex* sLogLock; - static std::queue sLogQueue; - static BOOL sLog; - static BOOL sMetricLog; - static std::string sLogName; - static bool sPauseHistory; - static bool sResetHistory; - - typedef std::vector info_list_t; - static info_list_t& getFrameStateList(); - - - // call this once a frame to reset timers - static void nextFrame(); - - // dumps current cumulative frame stats to log - // call nextFrame() to reset timers - static void dumpCurTimes(); - - // call this to reset timer hierarchy, averages, etc. - static void reset(); - - static U64 countsPerSecond(); - static S32 getLastFrameIndex() { return sLastFrameIndex; } - static S32 getCurFrameIndex() { return sCurFrameIndex; } - - static void writeLog(std::ostream& os); - static const NamedTimer* getTimerByName(const std::string& name); - - struct CurTimerData - { - LLFastTimer* mCurTimer; - FrameState* mFrameState; - U32 mChildTime; - }; - static CurTimerData sCurTimerData; - static std::string sClockType; - -private: - static U32 getCPUClockCount32(); - static U64 getCPUClockCount64(); - static U64 sClockResolution; - - static S32 sCurFrameIndex; - static S32 sLastFrameIndex; - static U64 sLastFrameTime; - static info_list_t* sTimerInfos; - - U32 mStartTime; - LLFastTimer::FrameState* mFrameState; - LLFastTimer::CurTimerData mLastTimerData; - -}; - -typedef class LLFastTimer LLFastTimer; - -#endif // LL_LLFASTTIMER_CLASS_H diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index 161cc418dd..c717a64501 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -1168,6 +1168,8 @@ static LLFastTimer::DeclareTimer FTM_SERVICE_CALLBACK("Callback"); static LLFastTimer::DeclareTimer FTM_AGENT_AUTOPILOT("Autopilot"); static LLFastTimer::DeclareTimer FTM_AGENT_UPDATE("Update"); +LLFastTimer::DeclareTimer FTM_FRAME("Frame"); + bool LLAppViewer::mainLoop() { LLMemType mt1(LLMemType::MTYPE_MAIN); @@ -1206,7 +1208,8 @@ bool LLAppViewer::mainLoop() // Handle messages while (!LLApp::isExiting()) { - LLFastTimer::nextFrame(); // Should be outside of any timer instances + LLFastTimer _(FTM_FRAME); + LLFastTimer::nextFrame(); //clear call stack records llclearcallstacks; @@ -3106,8 +3109,6 @@ void LLAppViewer::writeSystemInfo() LL_INFOS("SystemInfo") << "OS: " << getOSInfo().getOSStringSimple() << LL_ENDL; LL_INFOS("SystemInfo") << "OS info: " << getOSInfo() << LL_ENDL; - LL_INFOS("SystemInfo") << "Timers: " << LLFastTimer::sClockType << LL_ENDL; - writeDebugInfo(); // Save out debug_info.log early, in case of crash. } diff --git a/indra/newview/llappviewer.h b/indra/newview/llappviewer.h index f7d019ccba..304b084d39 100644 --- a/indra/newview/llappviewer.h +++ b/indra/newview/llappviewer.h @@ -41,6 +41,9 @@ class LLTextureFetch; class LLWatchdogTimeout; class LLUpdaterService; +extern LLFastTimer::DeclareTimer FTM_FRAME; + + class LLAppViewer : public LLApp { public: diff --git a/indra/newview/lldrawpoolbump.cpp b/indra/newview/lldrawpoolbump.cpp index 6f71e6ebc8..a340f43594 100644 --- a/indra/newview/lldrawpoolbump.cpp +++ b/indra/newview/lldrawpoolbump.cpp @@ -1192,7 +1192,7 @@ static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_MIN_MAX("Min/Max"); static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_RGB2LUM("RGB to Luminance"); static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_RESCALE("Rescale"); static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_GEN_NORMAL("Generate Normal"); -static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_CREATE("Create"); +static LLFastTimer::DeclareTimer FTM_BUMP_SOURCE_CREATE("Bump Source Create"); // static void LLBumpImageList::onSourceLoaded( BOOL success, LLViewerTexture *src_vi, LLImageRaw* src, LLUUID& source_asset_id, EBumpEffect bump_code ) diff --git a/indra/newview/llfasttimerview.cpp b/indra/newview/llfasttimerview.cpp index c032d5d049..59bf70f488 100644 --- a/indra/newview/llfasttimerview.cpp +++ b/indra/newview/llfasttimerview.cpp @@ -160,7 +160,7 @@ LLFastTimer::NamedTimer* LLFastTimerView::getLegendID(S32 y) BOOL LLFastTimerView::handleDoubleClick(S32 x, S32 y, MASK mask) { - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it) { @@ -257,7 +257,7 @@ BOOL LLFastTimerView::handleHover(S32 x, S32 y, MASK mask) } S32 i = 0; - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it, ++i) { @@ -419,11 +419,11 @@ void LLFastTimerView::draw() y -= (texth + 2); - sTimerColors[&LLFastTimer::NamedTimer::getRootNamedTimer()] = LLColor4::grey; + sTimerColors[&getFrameTimer()] = LLColor4::grey; F32 hue = 0.f; - for (timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for (timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != timer_tree_iterator_t(); ++it) { @@ -448,7 +448,7 @@ void LLFastTimerView::draw() S32 cur_line = 0; ft_display_idx.clear(); std::map display_line; - for (timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for (timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != timer_tree_iterator_t(); ++it) { @@ -558,7 +558,7 @@ void LLFastTimerView::draw() U64 totalticks; if (!LLFastTimer::sPauseHistory) { - U64 ticks = LLFastTimer::NamedTimer::getRootNamedTimer().getHistoricalCount(mScrollIndex); + U64 ticks = getFrameTimer().getHistoricalCount(mScrollIndex); if (LLFastTimer::getCurFrameIndex() >= 10) { @@ -598,7 +598,7 @@ void LLFastTimerView::draw() totalticks = 0; for (S32 j=0; j totalticks) totalticks = ticks; @@ -704,7 +704,7 @@ void LLFastTimerView::draw() LLFastTimer::NamedTimer* prev_id = NULL; S32 i = 0; - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it, ++i) { @@ -867,7 +867,7 @@ void LLFastTimerView::draw() } U64 cur_max = 0; - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it) { @@ -968,7 +968,7 @@ void LLFastTimerView::draw() { std::string legend_stat; bool first = true; - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it) { @@ -990,7 +990,7 @@ void LLFastTimerView::draw() std::string timer_stat; first = true; - for(timer_tree_iterator_t it = begin_timer_tree(LLFastTimer::NamedTimer::getRootNamedTimer()); + for(timer_tree_iterator_t it = begin_timer_tree(getFrameTimer()); it != end_timer_tree(); ++it) { @@ -1551,3 +1551,9 @@ void LLFastTimerView::onClickCloseBtn() setVisible(false); } +LLFastTimer::NamedTimer& LLFastTimerView::getFrameTimer() +{ + return FTM_FRAME.getNamedTimer(); +} + + diff --git a/indra/newview/llfasttimerview.h b/indra/newview/llfasttimerview.h index 1fda91f173..5766cfa0b0 100644 --- a/indra/newview/llfasttimerview.h +++ b/indra/newview/llfasttimerview.h @@ -46,6 +46,7 @@ private: static LLSD analyzePerformanceLogDefault(std::istream& is) ; static void exportCharts(const std::string& base, const std::string& target); void onPause(); + LLFastTimer::NamedTimer& getFrameTimer(); public: -- cgit v1.3 From d48889198b9f5b39c195e237ae253339b2d89ef3 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Thu, 30 Aug 2012 19:23:17 -0700 Subject: MAINT-1486 FIX Crash on login (Unhandled exception) open root timer by default --- indra/llcommon/llfasttimer.cpp | 1 + indra/newview/llappviewer.cpp | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/llcommon/llfasttimer.cpp b/indra/llcommon/llfasttimer.cpp index d54e1a93ea..6970c29092 100644 --- a/indra/llcommon/llfasttimer.cpp +++ b/indra/llcommon/llfasttimer.cpp @@ -116,6 +116,7 @@ public: mRootFrameState.setNamedTimer(mTimerRoot); mTimerRoot->setFrameState(&mRootFrameState); mTimerRoot->mParent = mTimerRoot; + mTimerRoot->setCollapsed(false); mRootFrameState.mParent = &mRootFrameState; } diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index bf01627bad..a8763aae0c 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -1178,7 +1178,7 @@ static LLFastTimer::DeclareTimer FTM_SERVICE_CALLBACK("Callback"); static LLFastTimer::DeclareTimer FTM_AGENT_AUTOPILOT("Autopilot"); static LLFastTimer::DeclareTimer FTM_AGENT_UPDATE("Update"); -LLFastTimer::DeclareTimer FTM_FRAME("Frame"); +LLFastTimer::DeclareTimer FTM_FRAME("Frame", true); bool LLAppViewer::mainLoop() { -- cgit v1.3 From e83700b56dcf2b0f392b49a79123b78bc7c8fbd9 Mon Sep 17 00:00:00 2001 From: Dave Parks Date: Fri, 30 Nov 2012 17:03:12 -0600 Subject: MAINT-1991 Attempt to mitigate crashes in GL drivers by encouraging people to update their drivers. Reviewed by Simon --- indra/newview/llappviewer.cpp | 17 +++++++--- indra/newview/llfeaturemanager.cpp | 11 +++++- indra/newview/llfeaturemanager.h | 5 ++- .../newview/skins/default/xui/en/notifications.xml | 39 ++++++++++++++++++++++ 4 files changed, 66 insertions(+), 6 deletions(-) (limited to 'indra/newview/llappviewer.cpp') diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp index f203ac224b..1000c0e1e8 100644 --- a/indra/newview/llappviewer.cpp +++ b/indra/newview/llappviewer.cpp @@ -1030,11 +1030,20 @@ bool LLAppViewer::init() } #if LL_WINDOWS - if (gGLManager.mIsIntel && - LLFeatureManager::getInstance()->getGPUClass() > 0 && - gGLManager.mGLVersion <= 3.f) + if (gGLManager.mGLVersion < LLFeatureManager::getInstance()->getExpectedGLVersion()) { - LLNotificationsUtil::add("IntelOldDriver"); + if (gGLManager.mIsIntel) + { + LLNotificationsUtil::add("IntelOldDriver"); + } + else if (gGLManager.mIsNVIDIA) + { + LLNotificationsUtil::add("NVIDIAOldDriver"); + } + else if (gGLManager.mIsATI) + { + LLNotificationsUtil::add("AMDOldDriver"); + } } #endif diff --git a/indra/newview/llfeaturemanager.cpp b/indra/newview/llfeaturemanager.cpp index b211027d54..564cb046ce 100644 --- a/indra/newview/llfeaturemanager.cpp +++ b/indra/newview/llfeaturemanager.cpp @@ -419,7 +419,7 @@ void LLFeatureManager::parseGPUTable(std::string filename) // setup the tokenizer std::string buf(buffer); - std::string cls, label, expr, supported; + std::string cls, label, expr, supported, stats_based, expected_gl_version; boost_tokenizer tokens(buf, boost::char_separator("\t\n")); boost_tokenizer::iterator token_iter = tokens.begin(); @@ -440,6 +440,14 @@ void LLFeatureManager::parseGPUTable(std::string filename) { supported = *token_iter++; } + if (token_iter != tokens.end()) + { + stats_based = *token_iter++; + } + if (token_iter != tokens.end()) + { + expected_gl_version = *token_iter++; + } if (label.empty() || expr.empty() || cls.empty() || supported.empty()) { @@ -469,6 +477,7 @@ void LLFeatureManager::parseGPUTable(std::string filename) mGPUString = label; mGPUClass = (EGPUClass) strtol(cls.c_str(), NULL, 10); mGPUSupported = (BOOL) strtol(supported.c_str(), NULL, 10); + sscanf(expected_gl_version.c_str(), "%f", &mExpectedGLVersion); } } #if LL_EXPORT_GPU_TABLE diff --git a/indra/newview/llfeaturemanager.h b/indra/newview/llfeaturemanager.h index 6f9d2e49c6..ad72c16743 100644 --- a/indra/newview/llfeaturemanager.h +++ b/indra/newview/llfeaturemanager.h @@ -103,7 +103,8 @@ public: mTableVersion(0), mSafe(FALSE), mGPUClass(GPU_CLASS_UNKNOWN), - mGPUSupported(FALSE) + mExpectedGLVersion(0.f), + mGPUSupported(FALSE) { } ~LLFeatureManager() {cleanupFeatureTables();} @@ -118,6 +119,7 @@ public: EGPUClass getGPUClass() { return mGPUClass; } std::string& getGPUString() { return mGPUString; } BOOL isGPUSupported() { return mGPUSupported; } + F32 getExpectedGLVersion() { return mExpectedGLVersion; } void cleanupFeatureTables(); @@ -157,6 +159,7 @@ protected: S32 mTableVersion; BOOL mSafe; // Reinitialize everything to the "safe" mask EGPUClass mGPUClass; + F32 mExpectedGLVersion; //expected GL version according to gpu table std::string mGPUString; BOOL mGPUSupported; }; diff --git a/indra/newview/skins/default/xui/en/notifications.xml b/indra/newview/skins/default/xui/en/notifications.xml index c32e23d553..648a1895c4 100644 --- a/indra/newview/skins/default/xui/en/notifications.xml +++ b/indra/newview/skins/default/xui/en/notifications.xml @@ -1291,6 +1291,45 @@ Visit [_URL] for more information? fail + + There is likely a newer driver for your graphics chip. Updating graphics drivers can substantially improve performance. + + Visit [_URL] to check for driver updates? + confirm + + http://support.amd.com/us/Pages/AMDSupportHub.aspx + + + fail + + + + There is likely a newer driver for your graphics chip. Updating graphics drivers can substantially improve performance. + + Visit [_URL] to check for driver updates? + confirm + + http://www.nvidia.com/Download/index.aspx?lang=en-us + + + fail + + +