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/llviewerstatsrecorder.cpp | 188 ++++++++++++++++++-------------- 1 file changed, 105 insertions(+), 83 deletions(-) (limited to 'indra/newview/llviewerstatsrecorder.cpp') 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 -- cgit v1.2.3 From 5564fcb271d993b1b8a98fae7f832f47f1236fd4 Mon Sep 17 00:00:00 2001 From: Richard Linden Date: Mon, 16 Jul 2012 19:15:46 -0700 Subject: SH-3275 WIP Run viewer metrics for object update messages clean up of llstats stuff --- indra/newview/llviewerstatsrecorder.cpp | 179 +++++++++++++++----------------- 1 file changed, 83 insertions(+), 96 deletions(-) (limited to 'indra/newview/llviewerstatsrecorder.cpp') diff --git a/indra/newview/llviewerstatsrecorder.cpp b/indra/newview/llviewerstatsrecorder.cpp index cfb446fe45..91e485d01b 100644 --- a/indra/newview/llviewerstatsrecorder.cpp +++ b/indra/newview/llviewerstatsrecorder.cpp @@ -27,7 +27,6 @@ #include "llviewerprecompiledheaders.h" #include "llviewerstatsrecorder.h" -#if LL_RECORD_VIEWER_STATS #include "llfile.h" #include "llviewerregion.h" @@ -46,8 +45,6 @@ LLViewerStatsRecorder::LLViewerStatsRecorder() : mObjectCacheFile(NULL), mTimer(), mStartTime(0.0), - mProcessingStartTime(0.0), - mProcessingTotalTime(0.0), mLastSnapshotTime(0.0) { if (NULL != sInstance) @@ -63,50 +60,12 @@ LLViewerStatsRecorder::~LLViewerStatsRecorder() if (mObjectCacheFile != NULL) { // last chance snapshot - takeSnapshot(); + writeToLog(0.f); LLFile::close(mObjectCacheFile); mObjectCacheFile = NULL; } } -void LLViewerStatsRecorder::beginObjectUpdateEvents(F32 interval) -{ - mSnapshotInterval = interval; - if (mObjectCacheFile == NULL) - { - mStartTime = LLTimer::getTotalSeconds(); - mObjectCacheFile = LLFile::fopen(STATS_FILE_NAME, "wb"); - if (mObjectCacheFile) - { // Write column headers - std::ostringstream data_msg; - 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 ); - } - } - mProcessingStartTime = LLTimer::getTotalSeconds(); -} - void LLViewerStatsRecorder::clearStats() { mObjectCacheHitCount = 0; @@ -128,6 +87,7 @@ void LLViewerStatsRecorder::clearStats() mObjectCacheUpdateReplacements = 0; mObjectUpdateFailures = 0; mObjectUpdateFailuresSize = 0; + mTextureFetchSize = 0; } @@ -204,69 +164,93 @@ void LLViewerStatsRecorder::recordRequestCacheMissesEvent(S32 count) mObjectCacheMissRequests += count; } -void LLViewerStatsRecorder::endObjectUpdateEvents() -{ - mProcessingTotalTime += LLTimer::getTotalSeconds() - mProcessingStartTime; - takeSnapshot(); -} - -void LLViewerStatsRecorder::takeSnapshot() +void LLViewerStatsRecorder::writeToLog( F32 interval ) { F64 delta_time = LLTimer::getTotalSeconds() - mLastSnapshotTime; - if ( delta_time > mSnapshotInterval) - { - 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; + S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures; - 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; + if ( delta_time < interval || total_objects == 0) return; - F32 processing32 = (F32) mProcessingTotalTime; - mProcessingTotalTime = 0.0; + mLastSnapshotTime = LLTimer::getTotalSeconds(); + lldebugs << "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 - << ", " << (mObjectCacheHitSize * 8 / delta_time) - << ", " << (mObjectCacheMissFullSize * 8 / delta_time) - << ", " << (mObjectCacheMissCrcSize * 8 / delta_time) - << ", " << (mObjectFullUpdatesSize * 8 / delta_time) - << ", " << (mObjectTerseUpdatesSize * 8 / delta_time) - << ", " << (mObjectCacheMissResponsesSize * 8 / delta_time) + if (mObjectCacheFile == NULL) + { + mStartTime = LLTimer::getTotalSeconds(); + mObjectCacheFile = LLFile::fopen(STATS_FILE_NAME, "wb"); + if (mObjectCacheFile) + { // Write column headers + std::ostringstream data_msg; + data_msg << "EventTime(ms)\t" + << "Cache Hits\t" + << "Cache Full Misses\t" + << "Cache Crc Misses\t" + << "Full Updates\t" + << "Terse Updates\t" + << "Cache Miss Requests\t" + << "Cache Miss Responses\t" + << "Cache Update Dupes\t" + << "Cache Update Changes\t" + << "Cache Update Adds\t" + << "Cache Update Replacements\t" + << "Update Failures\t" + << "Cache Hits bps\t" + << "Cache Full Misses bps\t" + << "Cache Crc Misses bps\t" + << "Full Updates bps\t" + << "Terse Updates bps\t" + << "Cache Miss Responses bps\t" + << "Texture Fetch bps\t" << "\n"; fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); } - - clearStats(); + else + { + llwarns << "Couldn't open " << STATS_FILE_NAME << " for logging." << llendl; + return; + } } + + std::ostringstream data_msg; + + data_msg << getTimeSinceStart() + << "\t " << mObjectCacheHitCount + << "\t" << mObjectCacheMissFullCount + << "\t" << mObjectCacheMissCrcCount + << "\t" << mObjectFullUpdates + << "\t" << mObjectTerseUpdates + << "\t" << mObjectCacheMissRequests + << "\t" << mObjectCacheMissResponses + << "\t" << mObjectCacheUpdateDupes + << "\t" << mObjectCacheUpdateChanges + << "\t" << mObjectCacheUpdateAdds + << "\t" << mObjectCacheUpdateReplacements + << "\t" << mObjectUpdateFailures + << "\t" << (mObjectCacheHitSize * 8 / delta_time) + << "\t" << (mObjectCacheMissFullSize * 8 / delta_time) + << "\t" << (mObjectCacheMissCrcSize * 8 / delta_time) + << "\t" << (mObjectFullUpdatesSize * 8 / delta_time) + << "\t" << (mObjectTerseUpdatesSize * 8 / delta_time) + << "\t" << (mObjectCacheMissResponsesSize * 8 / delta_time) + << "\t" << (mTextureFetchSize * 8 / delta_time) + << "\n"; + + fwrite(data_msg.str().c_str(), 1, data_msg.str().size(), mObjectCacheFile ); + clearStats(); } F32 LLViewerStatsRecorder::getTimeSinceStart() @@ -274,7 +258,10 @@ F32 LLViewerStatsRecorder::getTimeSinceStart() return (F32) (LLTimer::getTotalSeconds() - mStartTime); } -#endif +void LLViewerStatsRecorder::recordTextureFetch( S32 msg_size ) +{ + mTextureFetchSize += msg_size; +} -- cgit v1.2.3