livie
/
phoenix-firestorm
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

SH-3275 WIP Run viewer metrics for object update messages 

clean up of llstats stuff
master
Richard Linden 2012-07-16 19:15:46 -07:00
parent 5d32e23a11
commit 5564fcb271
19 changed files with 231 additions and 1215 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

46
indra/llcommon/llfasttimer_class.cpp
View File

@ -73,9 +73,6 @@ U64 LLFastTimer::sClockResolution = 1000000; // Microsecond resolution
#endif
std::vector<LLFastTimer::FrameState>* LLFastTimer::sTimerInfos = NULL;
U64 LLFastTimer::sTimerCycles = 0;
U32 LLFastTimer::sTimerCalls = 0;
// FIXME: move these declarations to the relevant modules
@ -425,8 +422,8 @@ void LLFastTimer::NamedTimer::buildHierarchy()
{
// since ancestors have already been visited, reparenting won't affect tree traversal
//step up tree, bringing our descendants with us
//llinfos << "Moving " << timerp->getName() << " from child of " << timerp->getParent()->getName() <<
// " to child of " << timerp->getParent()->getParent()->getName() << llendl;
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;
@ -507,12 +504,12 @@ void LLFastTimer::NamedTimer::resetFrame()
static S32 call_count = 0;
if (call_count % 100 == 0)
{
llinfos << "countsPerSecond (32 bit): " << countsPerSecond() << llendl;
llinfos << "get_clock_count (64 bit): " << get_clock_count() << llendl;
llinfos << "LLProcessorInfo().getCPUFrequency() " << LLProcessorInfo().getCPUFrequency() << llendl;
llinfos << "getCPUClockCount32() " << getCPUClockCount32() << llendl;
llinfos << "getCPUClockCount64() " << getCPUClockCount64() << llendl;
llinfos << "elapsed sec " << ((F64)getCPUClockCount64())/((F64)LLProcessorInfo().getCPUFrequency()*1000000.0) << llendl;
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++;
@ -566,26 +563,21 @@ void LLFastTimer::NamedTimer::resetFrame()
DeclareTimer::updateCachedPointers();
// reset for next frame
for (instance_iter it = beginInstances(); it != endInstances(); ++it)
{
for (instance_iter it = beginInstances(); it != endInstances(); ++it)
{
NamedTimer& timer = *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();
}
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();
}
}
//sTimerCycles = 0;
//sTimerCalls = 0;
}
//static

18
indra/llcommon/llfasttimer_class.h
View File

@ -30,7 +30,6 @@
#include "llinstancetracker.h"
#define FAST_TIMER_ON 1
#define TIME_FAST_TIMERS 0
#define DEBUG_FAST_TIMER_THREADS 1
class LLMutex;
@ -157,9 +156,6 @@ public:
LL_FORCE_INLINE LLFastTimer(LLFastTimer::DeclareTimer& timer)
: mFrameState(timer.mFrameState)
{
#if TIME_FAST_TIMERS
U64 timer_start = getCPUClockCount64();
#endif
#if FAST_TIMER_ON
LLFastTimer::FrameState* frame_state = mFrameState;
mStartTime = getCPUClockCount32();
@ -175,10 +171,6 @@ public:
cur_timer_data->mFrameState = frame_state;
cur_timer_data->mChildTime = 0;
#endif
#if TIME_FAST_TIMERS
U64 timer_end = getCPUClockCount64();
sTimerCycles += timer_end - timer_start;
#endif
#if DEBUG_FAST_TIMER_THREADS
#if !LL_RELEASE
assert_main_thread();
@ -188,9 +180,6 @@ public:
LL_FORCE_INLINE ~LLFastTimer()
{
#if TIME_FAST_TIMERS
U64 timer_start = getCPUClockCount64();
#endif
#if FAST_TIMER_ON
LLFastTimer::FrameState* frame_state = mFrameState;
U32 total_time = getCPUClockCount32() - mStartTime;
@ -206,11 +195,6 @@ public:
mLastTimerData.mChildTime += total_time;
LLFastTimer::sCurTimerData = mLastTimerData;
#endif
#if TIME_FAST_TIMERS
U64 timer_end = getCPUClockCount64();
sTimerCycles += timer_end - timer_start;
sTimerCalls++;
#endif
}
@ -222,8 +206,6 @@ public:
static std::string sLogName;
static bool sPauseHistory;
static bool sResetHistory;
static U64 sTimerCycles;
static U32 sTimerCalls;
typedef std::vector<FrameState> info_list_t;
static info_list_t& getFrameStateList();

713
indra/llcommon/llstat.cpp
View File

@ -37,715 +37,8 @@
// statics
S32 LLPerfBlock::sStatsFlags = LLPerfBlock::LLSTATS_NO_OPTIONAL_STATS; // Control what is being recorded
LLPerfBlock::stat_map_t LLPerfBlock::sStatMap; // Map full path string to LLStatTime objects, tracks all active objects
std::string LLPerfBlock::sCurrentStatPath = ""; // Something like "/total_time/physics/physics step"
LLStat::stat_map_t LLStat::sStatList;
//------------------------------------------------------------------------
// Live config file to trigger stats logging
static const char STATS_CONFIG_FILE_NAME[] = "/dev/shm/simperf/simperf_proc_config.llsd";
static const F32 STATS_CONFIG_REFRESH_RATE = 5.0; // seconds
class LLStatsConfigFile : public LLLiveFile
{
public:
LLStatsConfigFile()
: LLLiveFile(filename(), STATS_CONFIG_REFRESH_RATE),
mChanged(false), mStatsp(NULL) { }
static std::string filename();
protected:
/* virtual */ bool loadFile();
public:
void init(LLPerfStats* statsp);
static LLStatsConfigFile& instance();
// return the singleton stats config file
bool mChanged;
protected:
LLPerfStats* mStatsp;
};
std::string LLStatsConfigFile::filename()
{
return STATS_CONFIG_FILE_NAME;
}
void LLStatsConfigFile::init(LLPerfStats* statsp)
{
mStatsp = statsp;
}
LLStatsConfigFile& LLStatsConfigFile::instance()
{
static LLStatsConfigFile the_file;
return the_file;
}
/* virtual */
// Load and parse the stats configuration file
bool LLStatsConfigFile::loadFile()
{
if (!mStatsp)
{
llwarns << "Tries to load performance configure file without initializing LPerfStats" << llendl;
return false;
}
mChanged = true;
LLSD stats_config;
{
llifstream file(filename().c_str());
if (file.is_open())
{
LLSDSerialize::fromXML(stats_config, file);
if (stats_config.isUndefined())
{
llinfos << "Performance statistics configuration file ill-formed, not recording statistics" << llendl;
mStatsp->setReportPerformanceDuration( 0.f );
return false;
}
}
else
{ // File went away, turn off stats if it was on
if ( mStatsp->frameStatsIsRunning() )
{
llinfos << "Performance statistics configuration file deleted, not recording statistics" << llendl;
mStatsp->setReportPerformanceDuration( 0.f );
}
return true;
}
}
F32 duration = 0.f;
F32 interval = 0.f;
S32 flags = LLPerfBlock::LLSTATS_BASIC_STATS;
const char * w = "duration";
if (stats_config.has(w))
{
duration = (F32)stats_config[w].asReal();
}
w = "interval";
if (stats_config.has(w))
{
interval = (F32)stats_config[w].asReal();
}
w = "flags";
if (stats_config.has(w))
{
flags = (S32)stats_config[w].asInteger();
if (flags == LLPerfBlock::LLSTATS_NO_OPTIONAL_STATS &&
duration > 0)
{ // No flags passed in, but have a duration, so reset to basic stats
flags = LLPerfBlock::LLSTATS_BASIC_STATS;
}
}
mStatsp->setReportPerformanceDuration( duration, flags );
mStatsp->setReportPerformanceInterval( interval );
if ( duration > 0 )
{
if ( interval == 0.f )
{
llinfos << "Recording performance stats every frame for " << duration << " sec" << llendl;
}
else
{
llinfos << "Recording performance stats every " << interval << " seconds for " << duration << " seconds" << llendl;
}
}
else
{
llinfos << "Performance stats recording turned off" << llendl;
}
return true;
}
//------------------------------------------------------------------------
LLPerfStats::LLPerfStats(const std::string& process_name, S32 process_pid) :
mFrameStatsFileFailure(FALSE),
mSkipFirstFrameStats(FALSE),
mProcessName(process_name),
mProcessPID(process_pid),
mReportPerformanceStatInterval(1.f),
mReportPerformanceStatEnd(0.0)
{ }
LLPerfStats::~LLPerfStats()
{
LLPerfBlock::clearDynamicStats();
mFrameStatsFile.close();
}
void LLPerfStats::init()
{
// Initialize the stats config file instance.
(void) LLStatsConfigFile::instance().init(this);
(void) LLStatsConfigFile::instance().checkAndReload();
}
// Open file for statistics
void LLPerfStats::openPerfStatsFile()
{
if ( !mFrameStatsFile
&& !mFrameStatsFileFailure )
{
std::string stats_file = llformat("/dev/shm/simperf/%s_proc.%d.llsd", mProcessName.c_str(), mProcessPID);
mFrameStatsFile.close();
mFrameStatsFile.clear();
mFrameStatsFile.open(stats_file, llofstream::out);
if ( mFrameStatsFile.fail() )
{
llinfos << "Error opening statistics log file " << stats_file << llendl;
mFrameStatsFileFailure = TRUE;
}
else
{
LLSD process_info = LLSD::emptyMap();
process_info["name"] = mProcessName;
process_info["pid"] = (LLSD::Integer) mProcessPID;
process_info["stat_rate"] = (LLSD::Integer) mReportPerformanceStatInterval;
// Add process-specific info.
addProcessHeaderInfo(process_info);
mFrameStatsFile << LLSDNotationStreamer(process_info) << std::endl;
}
}
}
// Dump out performance metrics over some time interval
void LLPerfStats::dumpIntervalPerformanceStats()
{
// Ensure output file is OK
openPerfStatsFile();
if ( mFrameStatsFile )
{
LLSD stats = LLSD::emptyMap();
LLStatAccum::TimeScale scale;
if ( getReportPerformanceInterval() == 0.f )
{
scale = LLStatAccum::SCALE_PER_FRAME;
}
else if ( getReportPerformanceInterval() < 0.5f )
{
scale = LLStatAccum::SCALE_100MS;
}
else
{
scale = LLStatAccum::SCALE_SECOND;
}
// Write LLSD into log
stats["utc_time"] = (LLSD::String) LLError::utcTime();
stats["timestamp"] = U64_to_str((totalTime() / 1000) + (gUTCOffset * 1000)); // milliseconds since epoch
stats["frame_number"] = (LLSD::Integer) LLFrameTimer::getFrameCount();
// Add process-specific frame info.
addProcessFrameInfo(stats, scale);
LLPerfBlock::addStatsToLLSDandReset( stats, scale );
mFrameStatsFile << LLSDNotationStreamer(stats) << std::endl;
}
}
// Set length of performance stat recording.
// If turning stats on, caller must provide flags
void LLPerfStats::setReportPerformanceDuration( F32 seconds, S32 flags /* = LLSTATS_NO_OPTIONAL_STATS */ )
{
if ( seconds <= 0.f )
{
mReportPerformanceStatEnd = 0.0;
LLPerfBlock::setStatsFlags(LLPerfBlock::LLSTATS_NO_OPTIONAL_STATS); // Make sure all recording is off
mFrameStatsFile.close();
LLPerfBlock::clearDynamicStats();
}
else
{
mReportPerformanceStatEnd = LLFrameTimer::getElapsedSeconds() + ((F64) seconds);
// Clear failure flag to try and create the log file once
mFrameStatsFileFailure = FALSE;
mSkipFirstFrameStats = TRUE; // Skip the first report (at the end of this frame)
LLPerfBlock::setStatsFlags(flags);
}
}
void LLPerfStats::updatePerFrameStats()
{
(void) LLStatsConfigFile::instance().checkAndReload();
static LLFrameTimer performance_stats_timer;
if ( frameStatsIsRunning() )
{
if ( mReportPerformanceStatInterval == 0 )
{ // Record info every frame
if ( mSkipFirstFrameStats )
{ // Skip the first time - was started this frame
mSkipFirstFrameStats = FALSE;
}
else
{
dumpIntervalPerformanceStats();
}
}
else
{
performance_stats_timer.setTimerExpirySec( getReportPerformanceInterval() );
if (performance_stats_timer.checkExpirationAndReset( mReportPerformanceStatInterval ))
{
dumpIntervalPerformanceStats();
}
}
if ( LLFrameTimer::getElapsedSeconds() > mReportPerformanceStatEnd )
{ // Reached end of time, clear it to stop reporting
setReportPerformanceDuration(0.f); // Don't set mReportPerformanceStatEnd directly
llinfos << "Recording performance stats completed" << llendl;
}
}
}
//------------------------------------------------------------------------
U64 LLStatAccum::sScaleTimes[NUM_SCALES] =
{
USEC_PER_SEC / 10, // 100 millisec
USEC_PER_SEC * 1, // seconds
USEC_PER_SEC * 60, // minutes
#if ENABLE_LONG_TIME_STATS
// enable these when more time scales are desired
USEC_PER_SEC * 60*60, // hours
USEC_PER_SEC * 24*60*60, // days
USEC_PER_SEC * 7*24*60*60, // weeks
#endif
};
LLStatAccum::LLStatAccum(bool useFrameTimer)
: mUseFrameTimer(useFrameTimer),
mRunning(FALSE),
mLastTime(0),
mLastSampleValue(0.0),
mLastSampleValid(FALSE)
{
}
LLStatAccum::~LLStatAccum()
{
}
void LLStatAccum::reset(U64 when)
{
mRunning = TRUE;
mLastTime = when;
for (int i = 0; i < NUM_SCALES; ++i)
{
mBuckets[i].accum = 0.0;
mBuckets[i].endTime = when + sScaleTimes[i];
mBuckets[i].lastValid = false;
}
}
void LLStatAccum::sum(F64 value)
{
sum(value, getCurrentUsecs());
}
void LLStatAccum::sum(F64 value, U64 when)
{
if (!mRunning)
{
reset(when);
return;
}
if (when < mLastTime)
{
// This happens a LOT on some dual core systems.
lldebugs << "LLStatAccum::sum clock has gone backwards from "
<< mLastTime << " to " << when << ", resetting" << llendl;
reset(when);
return;
}
// how long is this value for
U64 timeSpan = when - mLastTime;
for (int i = 0; i < NUM_SCALES; ++i)
{
Bucket& bucket = mBuckets[i];
if (when < bucket.endTime)
{
bucket.accum += value;
}
else
{
U64 timeScale = sScaleTimes[i];
U64 timeLeft = when - bucket.endTime;
// how much time is left after filling this bucket
if (timeLeft < timeScale)
{
F64 valueLeft = value * timeLeft / timeSpan;
bucket.lastValid = true;
bucket.lastAccum = bucket.accum + (value - valueLeft);
bucket.accum = valueLeft;
bucket.endTime += timeScale;
}
else
{
U64 timeTail = timeLeft % timeScale;
bucket.lastValid = true;
bucket.lastAccum = value * timeScale / timeSpan;
bucket.accum = value * timeTail / timeSpan;
bucket.endTime += (timeLeft - timeTail) + timeScale;
}
}
}
mLastTime = when;
}
F32 LLStatAccum::meanValue(TimeScale scale) const
{
if (!mRunning)
{
return 0.0;
}
if ( scale == SCALE_PER_FRAME )
{ // Per-frame not supported here
scale = SCALE_100MS;
}
if (scale < 0 || scale >= NUM_SCALES)
{
llwarns << "llStatAccum::meanValue called for unsupported scale: "
<< scale << llendl;
return 0.0;
}
const Bucket& bucket = mBuckets[scale];
F64 value = bucket.accum;
U64 timeLeft = bucket.endTime - mLastTime;
U64 scaleTime = sScaleTimes[scale];
if (bucket.lastValid)
{
value += bucket.lastAccum * timeLeft / scaleTime;
}
else if (timeLeft < scaleTime)
{
value *= scaleTime / (scaleTime - timeLeft);
}
else
{
value = 0.0;
}
return (F32)(value / scaleTime);
}
U64 LLStatAccum::getCurrentUsecs() const
{
if (mUseFrameTimer)
{
return LLFrameTimer::getTotalTime();
}
else
{
return totalTime();
}
}
// ------------------------------------------------------------------------
LLStatRate::LLStatRate(bool use_frame_timer)
: LLStatAccum(use_frame_timer)
{
}
void LLStatRate::count(U32 value)
{
sum((F64)value * sScaleTimes[SCALE_SECOND]);
}
void LLStatRate::mark()
{
// Effectively the same as count(1), but sets mLastSampleValue
U64 when = getCurrentUsecs();
if ( mRunning
&& (when > mLastTime) )
{ // Set mLastSampleValue to the time from the last mark()
F64 duration = ((F64)(when - mLastTime)) / sScaleTimes[SCALE_SECOND];
if ( duration > 0.0 )
{
mLastSampleValue = 1.0 / duration;
}
else
{
mLastSampleValue = 0.0;
}
}
sum( (F64) sScaleTimes[SCALE_SECOND], when);
}
// ------------------------------------------------------------------------
LLStatMeasure::LLStatMeasure(bool use_frame_timer)
: LLStatAccum(use_frame_timer)
{
}
void LLStatMeasure::sample(F64 value)
{
U64 when = getCurrentUsecs();
if (mLastSampleValid)
{
F64 avgValue = (value + mLastSampleValue) / 2.0;
F64 interval = (F64)(when - mLastTime);
sum(avgValue * interval, when);
}
else
{
reset(when);
}
mLastSampleValid = TRUE;
mLastSampleValue = value;
}
// ------------------------------------------------------------------------
LLStatTime::LLStatTime(const std::string & key)
: LLStatAccum(false),
mFrameNumber(LLFrameTimer::getFrameCount()),
mTotalTimeInFrame(0),
mKey(key)
#if LL_DEBUG
, mRunning(FALSE)
#endif
{
}
void LLStatTime::start()
{
// Reset frame accumluation if the frame number has changed
U32 frame_number = LLFrameTimer::getFrameCount();
if ( frame_number != mFrameNumber )
{
mFrameNumber = frame_number;
mTotalTimeInFrame = 0;
}
sum(0.0);
#if LL_DEBUG
// Shouldn't be running already
llassert( !mRunning );
mRunning = TRUE;
#endif
}
void LLStatTime::stop()
{
U64 end_time = getCurrentUsecs();
U64 duration = end_time - mLastTime;
sum(F64(duration), end_time);
//llinfos << "mTotalTimeInFrame incremented from " << mTotalTimeInFrame << " to " << (mTotalTimeInFrame + duration) << llendl;
mTotalTimeInFrame += duration;
#if LL_DEBUG
mRunning = FALSE;
#endif
}
/* virtual */ F32 LLStatTime::meanValue(TimeScale scale) const
{
if ( LLStatAccum::SCALE_PER_FRAME == scale )
{
return (F32)mTotalTimeInFrame;
}
else
{
return LLStatAccum::meanValue(scale);
}
}
// ------------------------------------------------------------------------
// Use this constructor for pre-defined LLStatTime objects
LLPerfBlock::LLPerfBlock(LLStatTime* stat ) : mPredefinedStat(stat), mDynamicStat(NULL)
{
if (mPredefinedStat)
{
// If dynamic stats are turned on, this will create a separate entry in the stat map.
initDynamicStat(mPredefinedStat->mKey);
// Start predefined stats. These stats are not part of the stat map.
mPredefinedStat->start();
}
}
// Use this constructor for normal, optional LLPerfBlock time slices
LLPerfBlock::LLPerfBlock( const char* key ) : mPredefinedStat(NULL), mDynamicStat(NULL)
{
if ((sStatsFlags & LLSTATS_BASIC_STATS) == 0)
{ // These are off unless the base set is enabled
return;
}
initDynamicStat(key);
}
// Use this constructor for dynamically created LLPerfBlock time slices
// that are only enabled by specific control flags
LLPerfBlock::LLPerfBlock( const char* key1, const char* key2, S32 flags ) : mPredefinedStat(NULL), mDynamicStat(NULL)
{
if ((sStatsFlags & flags) == 0)
{
return;
}
if (NULL == key2 || strlen(key2) == 0)
{
initDynamicStat(key1);
}
else
{
std::ostringstream key;
key << key1 << "_" << key2;
initDynamicStat(key.str());
}
}
// Set up the result data map if dynamic stats are enabled
void LLPerfBlock::initDynamicStat(const std::string& key)
{
// Early exit if dynamic stats aren't enabled.
if (sStatsFlags == LLSTATS_NO_OPTIONAL_STATS)
return;
mLastPath = sCurrentStatPath; // Save and restore current path
sCurrentStatPath += "/" + key; // Add key to current path
// See if the LLStatTime object already exists
stat_map_t::iterator iter = sStatMap.find(sCurrentStatPath);
if ( iter == sStatMap.end() )
{
// StatEntry object doesn't exist, so create it
mDynamicStat = new StatEntry( key );
sStatMap[ sCurrentStatPath ] = mDynamicStat; // Set the entry for this path
}
else
{
// Found this path in the map, use the object there
mDynamicStat = (*iter).second; // Get StatEntry for the current path
}
if (mDynamicStat)
{
mDynamicStat->mStat.start();
mDynamicStat->mCount++;
}
else
{
llwarns << "Initialized NULL dynamic stat at '" << sCurrentStatPath << "'" << llendl;
sCurrentStatPath = mLastPath;
}
}
// Destructor does the time accounting
LLPerfBlock::~LLPerfBlock()
{
if (mPredefinedStat) mPredefinedStat->stop();
if (mDynamicStat)
{
mDynamicStat->mStat.stop();
sCurrentStatPath = mLastPath; // Restore the path in case sStatsEnabled changed during this block
}
}
// Clear the map of any dynamic stats. Static routine
void LLPerfBlock::clearDynamicStats()
{
std::for_each(sStatMap.begin(), sStatMap.end(), DeletePairedPointer());
sStatMap.clear();
}
// static - Extract the stat info into LLSD
void LLPerfBlock::addStatsToLLSDandReset( LLSD & stats,
LLStatAccum::TimeScale scale )
{
// If we aren't in per-frame scale, we need to go from second to microsecond.
U32 scale_adjustment = 1;
if (LLStatAccum::SCALE_PER_FRAME != scale)
{
scale_adjustment = USEC_PER_SEC;
}
stat_map_t::iterator iter = sStatMap.begin();
for ( ; iter != sStatMap.end(); ++iter )
{ // Put the entry into LLSD "/full/path/to/stat/" = microsecond total time
const std::string & stats_full_path = (*iter).first;
StatEntry * stat = (*iter).second;
if (stat)
{
if (stat->mCount > 0)
{
stats[stats_full_path] = LLSD::emptyMap();
stats[stats_full_path]["us"] = (LLSD::Integer) (scale_adjustment * stat->mStat.meanValue(scale));
if (stat->mCount > 1)
{
stats[stats_full_path]["count"] = (LLSD::Integer) stat->mCount;
}
stat->mCount = 0;
}
}
else
{ // Shouldn't have a NULL pointer in the map.
llwarns << "Unexpected NULL dynamic stat at '" << stats_full_path << "'" << llendl;
}
}
}
// ------------------------------------------------------------------------
LLTimer LLStat::sTimer;
LLFrameTimer LLStat::sFrameTimer;
@ -786,9 +79,9 @@ LLStat::LLStat(const U32 num_bins, const BOOL use_frame_timer)
}
LLStat::LLStat(std::string name, U32 num_bins, BOOL use_frame_timer)
: mUseFrameTimer(use_frame_timer),
mNumBins(num_bins),
mName(name)
: mUseFrameTimer(use_frame_timer),
mNumBins(num_bins),
mName(name)
{
init();
}

222
indra/llcommon/llstat.h
View File

@ -36,228 +36,6 @@
class LLSD;
// Set this if longer stats are needed
#define ENABLE_LONG_TIME_STATS 0
//
// Accumulates statistics for an arbitrary length of time.
// Does this by maintaining a chain of accumulators, each one
// accumulation the results of the parent. Can scale to arbitrary
// amounts of time with very low memory cost.
//
class LL_COMMON_API LLStatAccum
{
protected:
LLStatAccum(bool use_frame_timer);
virtual ~LLStatAccum();
public:
enum TimeScale {
SCALE_100MS,
SCALE_SECOND,
SCALE_MINUTE,
#if ENABLE_LONG_TIME_STATS
SCALE_HOUR,
SCALE_DAY,
SCALE_WEEK,
#endif
NUM_SCALES, // Use to size storage arrays
SCALE_PER_FRAME // For latest frame information - should be after NUM_SCALES since this doesn't go into the time buckets
};
static U64 sScaleTimes[NUM_SCALES];
virtual F32 meanValue(TimeScale scale) const;
// see the subclasses for the specific meaning of value
F32 meanValueOverLast100ms() const { return meanValue(SCALE_100MS); }
F32 meanValueOverLastSecond() const { return meanValue(SCALE_SECOND); }
F32 meanValueOverLastMinute() const { return meanValue(SCALE_MINUTE); }
void reset(U64 when);
void sum(F64 value);
void sum(F64 value, U64 when);
U64 getCurrentUsecs() const;
// Get current microseconds based on timer type
BOOL mUseFrameTimer;
BOOL mRunning;
U64 mLastTime;
struct Bucket
{
Bucket() :
accum(0.0),
endTime(0),
lastValid(false),
lastAccum(0.0)
{}
F64 accum;
U64 endTime;
bool lastValid;
F64 lastAccum;
};
Bucket mBuckets[NUM_SCALES];
BOOL mLastSampleValid;
F64 mLastSampleValue;
};
class LL_COMMON_API LLStatMeasure : public LLStatAccum
// gathers statistics about things that are measured
// ex.: tempature, time dilation
{
public:
LLStatMeasure(bool use_frame_timer = true);
void sample(F64);
void sample(S32 v) { sample((F64)v); }
void sample(U32 v) { sample((F64)v); }
void sample(S64 v) { sample((F64)v); }
void sample(U64 v) { sample((F64)v); }
};
class LL_COMMON_API LLStatRate : public LLStatAccum
// gathers statistics about things that can be counted over time
// ex.: LSL instructions executed, messages sent, simulator frames completed
// renders it in terms of rate of thing per second
{
public:
LLStatRate(bool use_frame_timer = true);
void count(U32);
// used to note that n items have occured
void mark();
// used for counting the rate thorugh a point in the code
};
class LL_COMMON_API LLStatTime : public LLStatAccum
// gathers statistics about time spent in a block of code
// measure average duration per second in the block
{
public:
LLStatTime( const std::string & key = "undefined" );
U32 mFrameNumber; // Current frame number
U64 mTotalTimeInFrame; // Total time (microseconds) accumulated during the last frame
void setKey( const std::string & key ) { mKey = key; };
virtual F32 meanValue(TimeScale scale) const;
private:
void start(); // Start and stop measuring time block
void stop();
std::string mKey; // Tag representing this time block
#if LL_DEBUG
BOOL mRunning; // TRUE if start() has been called
#endif
friend class LLPerfBlock;
};
// ----------------------------------------------------------------------------
// Use this class on the stack to record statistics about an area of code
class LL_COMMON_API LLPerfBlock
{
public:
struct StatEntry
{
StatEntry(const std::string& key) : mStat(LLStatTime(key)), mCount(0) {}
LLStatTime mStat;
U32 mCount;
};
typedef std::map<std::string, StatEntry*> stat_map_t;
// Use this constructor for pre-defined LLStatTime objects
LLPerfBlock(LLStatTime* stat);
// Use this constructor for normal, optional LLPerfBlock time slices
LLPerfBlock( const char* key );
// Use this constructor for dynamically created LLPerfBlock time slices
// that are only enabled by specific control flags
LLPerfBlock( const char* key1, const char* key2, S32 flags = LLSTATS_BASIC_STATS );
~LLPerfBlock();
enum
{ // Stats bitfield flags
LLSTATS_NO_OPTIONAL_STATS = 0x00, // No optional stats gathering, just pre-defined LLStatTime objects
LLSTATS_BASIC_STATS = 0x01, // Gather basic optional runtime stats
LLSTATS_SCRIPT_FUNCTIONS = 0x02, // Include LSL function calls
};
static void setStatsFlags( S32 flags ) { sStatsFlags = flags; };
static S32 getStatsFlags() { return sStatsFlags; };
static void clearDynamicStats(); // Reset maps to clear out dynamic objects
static void addStatsToLLSDandReset( LLSD & stats, // Get current information and clear time bin
LLStatAccum::TimeScale scale );
private:
// Initialize dynamically created LLStatTime objects
void initDynamicStat(const std::string& key);
std::string mLastPath; // Save sCurrentStatPath when this is called
LLStatTime * mPredefinedStat; // LLStatTime object to get data
StatEntry * mDynamicStat; // StatEntryobject to get data
static S32 sStatsFlags; // Control what is being recorded
static stat_map_t sStatMap; // Map full path string to LLStatTime objects
static std::string sCurrentStatPath; // Something like "frame/physics/physics step"
};
// ----------------------------------------------------------------------------
class LL_COMMON_API LLPerfStats
{
public:
LLPerfStats(const std::string& process_name = "unknown", S32 process_pid = 0);
virtual ~LLPerfStats();
virtual void init(); // Reset and start all stat timers
virtual void updatePerFrameStats();
// Override these function to add process-specific information to the performance log header and per-frame logging.
virtual void addProcessHeaderInfo(LLSD& info) { /* not implemented */ }
virtual void addProcessFrameInfo(LLSD& info, LLStatAccum::TimeScale scale) { /* not implemented */ }
// High-resolution frame stats
BOOL frameStatsIsRunning() { return (mReportPerformanceStatEnd > 0.); };
F32 getReportPerformanceInterval() const { return mReportPerformanceStatInterval; };
void setReportPerformanceInterval( F32 interval ) { mReportPerformanceStatInterval = interval; };
void setReportPerformanceDuration( F32 seconds, S32 flags = LLPerfBlock::LLSTATS_NO_OPTIONAL_STATS );
void setProcessName(const std::string& process_name) { mProcessName = process_name; }
void setProcessPID(S32 process_pid) { mProcessPID = process_pid; }
protected:
void openPerfStatsFile(); // Open file for high resolution metrics logging
void dumpIntervalPerformanceStats();
llofstream mFrameStatsFile; // File for per-frame stats
BOOL mFrameStatsFileFailure; // Flag to prevent repeat opening attempts
BOOL mSkipFirstFrameStats; // Flag to skip one (partial) frame report
std::string mProcessName;
S32 mProcessPID;
private:
F32 mReportPerformanceStatInterval; // Seconds between performance stats
F64 mReportPerformanceStatEnd; // End time (seconds) for performance stats
};
// ----------------------------------------------------------------------------
class LL_COMMON_API LLStat
{

2
indra/llmessage/llcircuit.cpp
View File

@ -679,7 +679,6 @@ void LLCircuitData::checkPacketInID(TPACKETID id, BOOL receive_resent)
setPacketInID((id + 1) % LL_MAX_OUT_PACKET_ID);
mLastPacketGap = 0;
mOutOfOrderRate.count(0);
return;
}
@ -775,7 +774,6 @@ void LLCircuitData::checkPacketInID(TPACKETID id, BOOL receive_resent)
}
}
mOutOfOrderRate.count(gap);
mLastPacketGap = gap;
}

3
indra/llmessage/llcircuit.h
View File

@ -126,8 +126,6 @@ public:
S32 getUnackedPacketCount() const { return mUnackedPacketCount; }
S32 getUnackedPacketBytes() const { return mUnackedPacketBytes; }
F64 getNextPingSendTime() const { return mNextPingSendTime; }
F32 getOutOfOrderRate(LLStatAccum::TimeScale scale = LLStatAccum::SCALE_MINUTE)
{ return mOutOfOrderRate.meanValue(scale); }
U32 getLastPacketGap() const { return mLastPacketGap; }
LLHost getHost() const { return mHost; }
F64 getLastPacketInTime() const { return mLastPacketInTime; }
@ -275,7 +273,6 @@ protected:
LLTimer mExistenceTimer; // initialized when circuit created, used to track bandwidth numbers
S32 mCurrentResendCount; // Number of resent packets since last spam
LLStatRate mOutOfOrderRate; // Rate of out of order packets coming in.
U32 mLastPacketGap; // Gap in sequence number of last packet.
const F32 mHeartbeatInterval;

13
indra/llmessage/lliohttpserver.cpp
View File

@ -141,6 +141,11 @@ private:
};
static LLFastTimer::DeclareTimer FTM_PROCESS_HTTP_PIPE("HTTP Pipe");
static LLFastTimer::DeclareTimer FTM_PROCESS_HTTP_GET("HTTP Get");
static LLFastTimer::DeclareTimer FTM_PROCESS_HTTP_PUT("HTTP Put");
static LLFastTimer::DeclareTimer FTM_PROCESS_HTTP_POST("HTTP Post");
static LLFastTimer::DeclareTimer FTM_PROCESS_HTTP_DELETE("HTTP Delete");
LLIOPipe::EStatus LLHTTPPipe::process_impl(
const LLChannelDescriptors& channels,
buffer_ptr_t& buffer,
@ -177,12 +182,12 @@ LLIOPipe::EStatus LLHTTPPipe::process_impl(
std::string verb = context[CONTEXT_REQUEST][CONTEXT_VERB];
if(verb == HTTP_VERB_GET)
{
LLPerfBlock getblock("http_get");
LLFastTimer _(FTM_PROCESS_HTTP_GET);
mNode.get(LLHTTPNode::ResponsePtr(mResponse), context);
}
else if(verb == HTTP_VERB_PUT)
{
LLPerfBlock putblock("http_put");
LLFastTimer _(FTM_PROCESS_HTTP_PUT);
LLSD input;
if (mNode.getContentType() == LLHTTPNode::CONTENT_TYPE_LLSD)
{
@ -198,7 +203,7 @@ LLIOPipe::EStatus LLHTTPPipe::process_impl(
}
else if(verb == HTTP_VERB_POST)
{
LLPerfBlock postblock("http_post");
LLFastTimer _(FTM_PROCESS_HTTP_POST);
LLSD input;
if (mNode.getContentType() == LLHTTPNode::CONTENT_TYPE_LLSD)
{
@ -214,7 +219,7 @@ LLIOPipe::EStatus LLHTTPPipe::process_impl(
}
else if(verb == HTTP_VERB_DELETE)
{
LLPerfBlock delblock("http_delete");
LLFastTimer _(FTM_PROCESS_HTTP_DELETE);
mNode.del(LLHTTPNode::ResponsePtr(mResponse), context);
}
else if(verb == HTTP_VERB_OPTIONS)

2
indra/llmessage/llmessagetemplate.h
View File

@ -263,6 +263,7 @@ enum EMsgDeprecation
MD_DEPRECATED
};
class LLMessageTemplate
{
public:
@ -364,7 +365,6 @@ public:
{
if (mHandlerFunc)
{
LLPerfBlock msg_cb_time("msg_cb", mName);
mHandlerFunc(msgsystem, mUserData);
return TRUE;
}

3
indra/llmessage/llpumpio.cpp
View File

@ -441,6 +441,7 @@ void LLPumpIO::pump()
}
static LLFastTimer::DeclareTimer FTM_PUMP_IO("Pump IO");
static LLFastTimer::DeclareTimer FTM_PUMP_POLL("Pump Poll");
LLPumpIO::current_chain_t LLPumpIO::removeRunningChain(LLPumpIO::current_chain_t& run_chain)
{
@ -536,7 +537,7 @@ void LLPumpIO::pump(const S32& poll_timeout)
S32 count = 0;
S32 client_id = 0;
{
LLPerfBlock polltime("pump_poll");
LLFastTimer _(FTM_PUMP_POLL);
apr_pollset_poll(mPollset, poll_timeout, &count, &poll_fd);
}
PUMP_DEBUG;

18
indra/newview/app_settings/logcontrol.xml
View File

@ -48,24 +48,6 @@
-->
</array>
</map>
<map>
<key>level</key>
<string>NONE</string>
<key>functions</key>
<array>
</array>
<key>classes</key>
<array>
<string>LLViewerStatsRecorder</string>
</array>
<key>files</key>
<array>
</array>
<key>tags</key>
<array>
</array>
</map>
</array>
</map>
</llsd>

12
indra/newview/llfasttimerview.cpp
View File

@ -95,7 +95,6 @@ LLFastTimerView::LLFastTimerView(const LLSD& key)
mHoverBarIndex = -1;
FTV_NUM_TIMERS = LLFastTimer::NamedTimer::instanceCount();
mPrintStats = -1;
mAverageCyclesPerTimer = 0;
}
void LLFastTimerView::onPause()
@ -379,12 +378,6 @@ void LLFastTimerView::draw()
S32 xleft = margin;
S32 ytop = margin;
mAverageCyclesPerTimer = LLFastTimer::sTimerCalls == 0
? 0
: llround(lerp((F32)mAverageCyclesPerTimer, (F32)(LLFastTimer::sTimerCycles / (U64)LLFastTimer::sTimerCalls), 0.1f));
LLFastTimer::sTimerCycles = 0;
LLFastTimer::sTimerCalls = 0;
// Draw some help
{
@ -392,10 +385,6 @@ void LLFastTimerView::draw()
y = height - ytop;
texth = (S32)LLFontGL::getFontMonospace()->getLineHeight();
#if TIME_FAST_TIMERS
tdesc = llformat("Cycles per timer call: %d", mAverageCyclesPerTimer);
LLFontGL::getFontMonospace()->renderUTF8(tdesc, 0, x, y, LLColor4::white, LLFontGL::LEFT, LLFontGL::TOP);
#else
char modedesc[][32] = {
"2 x Average ",
"Max ",
@ -419,7 +408,6 @@ void LLFastTimerView::draw()
LLFontGL::getFontMonospace()->renderUTF8(std::string("[Right-Click log selected] [ALT-Click toggle counts] [ALT-SHIFT-Click sub hidden]"),
0, x, y, LLColor4::white, LLFontGL::LEFT, LLFontGL::TOP);
#endif
y -= (texth + 2);
}

1
indra/newview/llfasttimerview.h
View File

@ -90,7 +90,6 @@ private:
S32 mHoverBarIndex;
LLFrameTimer mHighlightTimer;
S32 mPrintStats;
S32 mAverageCyclesPerTimer;
LLRect mGraphRect;
};

9
indra/newview/lltexturefetch.cpp
View File

@ -50,6 +50,7 @@
#include "llviewertexture.h"
#include "llviewerregion.h"
#include "llviewerstats.h"
#include "llviewerstatsrecorder.h"
#include "llviewerassetstats.h"
#include "llworld.h"
#include "llsdutil.h"
@ -1703,6 +1704,7 @@ S32 LLTextureFetchWorker::callbackHttpGet(const LLChannelDescriptors& channels,
LL_DEBUGS("Texture") << "HTTP RECEIVED: " << mID.asString() << " Bytes: " << data_size << LL_ENDL;
if (data_size > 0)
{
LLViewerStatsRecorder::instance().textureFetch(data_size);
// *TODO: set the formatted image data here directly to avoid the copy
mBuffer = (U8*)ALLOCATE_MEM(LLImageBase::getPrivatePool(), data_size);
buffer->readAfter(channels.in(), NULL, mBuffer, data_size);
@ -1736,6 +1738,7 @@ S32 LLTextureFetchWorker::callbackHttpGet(const LLChannelDescriptors& channels,
mLoaded = TRUE;
setPriority(LLWorkerThread::PRIORITY_HIGH | mWorkPriority);
LLViewerStatsRecorder::instance().log(0.2f);
return data_size ;
}
@ -2639,6 +2642,9 @@ bool LLTextureFetch::receiveImageHeader(const LLHost& host, const LLUUID& id, U8
return false;
}
LLViewerStatsRecorder::instance().textureFetch(data_size);
LLViewerStatsRecorder::instance().log(0.1f);
worker->lockWorkMutex();
// Copy header data into image object
@ -2685,6 +2691,9 @@ bool LLTextureFetch::receiveImagePacket(const LLHost& host, const LLUUID& id, U1
return false;
}
LLViewerStatsRecorder::instance().textureFetch(data_size);
LLViewerStatsRecorder::instance().log(0.1f);
worker->lockWorkMutex();
res = worker->insertPacket(packet_num, data, data_size);

37
indra/newview/llviewerobjectlist.cpp
View File

@ -347,9 +347,6 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
LLDataPackerBinaryBuffer compressed_dp(compressed_dpbuffer, 2048);
LLDataPacker *cached_dpp = NULL;
LLViewerStatsRecorder& recorder = LLViewerStatsRecorder::instance();
#if LL_RECORD_VIEWER_STATS
recorder.beginObjectUpdateEvents(1.f);
#endif
for (i = 0; i < num_objects; i++)
{
@ -380,9 +377,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
else
{
// Cache Miss.
#if LL_RECORD_VIEWER_STATS
recorder.recordCacheMissEvent(id, update_type, cache_miss_type, msg_size);
#endif
recorder.cacheMissEvent(id, update_type, cache_miss_type, msg_size);
continue; // no data packer, skip this object
}
@ -509,9 +504,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
if (update_type == OUT_TERSE_IMPROVED)
{
// llinfos << "terse update for an unknown object (compressed):" << fullid << llendl;
#if LL_RECORD_VIEWER_STATS
recorder.recordObjectUpdateFailure(local_id, update_type, msg_size);
#endif
recorder.objectUpdateFailure(local_id, update_type, msg_size);
continue;
}
}
@ -523,9 +516,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
if (update_type != OUT_FULL)
{
//llinfos << "terse update for an unknown object:" << fullid << llendl;
#if LL_RECORD_VIEWER_STATS
recorder.recordObjectUpdateFailure(local_id, update_type, msg_size);
#endif
recorder.objectUpdateFailure(local_id, update_type, msg_size);
continue;
}
@ -538,9 +529,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
{
mNumDeadObjectUpdates++;
//llinfos << "update for a dead object:" << fullid << llendl;
#if LL_RECORD_VIEWER_STATS
recorder.recordObjectUpdateFailure(local_id, update_type, msg_size);
#endif
recorder.objectUpdateFailure(local_id, update_type, msg_size);
continue;
}
#endif
@ -549,9 +538,7 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
if (!objectp)
{
llinfos << "createObject failure for object: " << fullid << llendl;
#if LL_RECORD_VIEWER_STATS
recorder.recordObjectUpdateFailure(local_id, update_type, msg_size);
#endif
recorder.objectUpdateFailure(local_id, update_type, msg_size);
continue;
}
justCreated = TRUE;
@ -577,12 +564,8 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
if (update_type != OUT_TERSE_IMPROVED) // OUT_FULL_COMPRESSED only?
{
bCached = true;
#if LL_RECORD_VIEWER_STATS
LLViewerRegion::eCacheUpdateResult result = objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp);
recorder.recordCacheFullUpdate(local_id, update_type, result, objectp, msg_size);
#else
objectp->mRegionp->cacheFullUpdate(objectp, compressed_dp);
#endif
recorder.cacheFullUpdate(local_id, update_type, result, objectp, msg_size);
}
}
else if (cached) // Cache hit only?
@ -598,16 +581,12 @@ void LLViewerObjectList::processObjectUpdate(LLMessageSystem *mesgsys,
}
processUpdateCore(objectp, user_data, i, update_type, NULL, justCreated);
}
#if LL_RECORD_VIEWER_STATS
recorder.recordObjectUpdateEvent(local_id, update_type, objectp, msg_size);
#endif
recorder.objectUpdateEvent(local_id, update_type, objectp, msg_size);
objectp->setLastUpdateType(update_type);
objectp->setLastUpdateCached(bCached);
}
#if LL_RECORD_VIEWER_STATS
recorder.endObjectUpdateEvents();
#endif
recorder.log(0.2f);
LLVOAvatar::cullAvatarsByPixelArea();
}

7
indra/newview/llviewerregion.cpp
View File

@ -1317,11 +1317,8 @@ 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(1.f);
LLViewerStatsRecorder::instance().recordRequestCacheMissesEvent(full_count + crc_count);
LLViewerStatsRecorder::instance().endObjectUpdateEvents();
#endif
LLViewerStatsRecorder::instance().requestCacheMissesEvent(full_count + crc_count);
LLViewerStatsRecorder::instance().log(0.2f);
}
void LLViewerRegion::dumpCache()

89
indra/newview/llviewerstats.cpp
View File

@ -323,55 +323,55 @@ void LLViewerStats::updateFrameStats(const F64 time_diff)
{
if (mPacketsLostPercentStat.getCurrent() > 5.0)
{
incStat(LLViewerStats::ST_LOSS_05_SECONDS, time_diff);
incStat(ST_LOSS_05_SECONDS, time_diff);
}
if (mSimFPS.getCurrent() < 20.f && mSimFPS.getCurrent() > 0.f)
{
incStat(LLViewerStats::ST_SIM_FPS_20_SECONDS, time_diff);
incStat(ST_SIM_FPS_20_SECONDS, time_diff);
}
if (mSimPhysicsFPS.getCurrent() < 20.f && mSimPhysicsFPS.getCurrent() > 0.f)
{
incStat(LLViewerStats::ST_PHYS_FPS_20_SECONDS, time_diff);
incStat(ST_PHYS_FPS_20_SECONDS, time_diff);
}
if (time_diff >= 0.5)
{
incStat(LLViewerStats::ST_FPS_2_SECONDS, time_diff);
incStat(ST_FPS_2_SECONDS, time_diff);
}
if (time_diff >= 0.125)
{
incStat(LLViewerStats::ST_FPS_8_SECONDS, time_diff);
incStat(ST_FPS_8_SECONDS, time_diff);
}
if (time_diff >= 0.1)
{
incStat(LLViewerStats::ST_FPS_10_SECONDS, time_diff);
incStat(ST_FPS_10_SECONDS, time_diff);
}
if (gFrameCount && mLastTimeDiff > 0.0)
{
// new "stutter" meter
setStat(LLViewerStats::ST_FPS_DROP_50_RATIO,
(getStat(LLViewerStats::ST_FPS_DROP_50_RATIO) * (F64)(gFrameCount - 1) +
setStat(ST_FPS_DROP_50_RATIO,
(getStat(ST_FPS_DROP_50_RATIO) * (F64)(gFrameCount - 1) +
(time_diff >= 2.0 * mLastTimeDiff ? 1.0 : 0.0)) / gFrameCount);
// old stats that were never really used
setStat(LLViewerStats::ST_FRAMETIME_JITTER,
(getStat(LLViewerStats::ST_FRAMETIME_JITTER) * (gFrameCount - 1) +
setStat(ST_FRAMETIME_JITTER,
(getStat(ST_FRAMETIME_JITTER) * (gFrameCount - 1) +
fabs(mLastTimeDiff - time_diff) / mLastTimeDiff) / gFrameCount);
F32 average_frametime = gRenderStartTime.getElapsedTimeF32() / (F32)gFrameCount;
setStat(LLViewerStats::ST_FRAMETIME_SLEW,
(getStat(LLViewerStats::ST_FRAMETIME_SLEW) * (gFrameCount - 1) +
setStat(ST_FRAMETIME_SLEW,
(getStat(ST_FRAMETIME_SLEW) * (gFrameCount - 1) +
fabs(average_frametime - time_diff) / average_frametime) / gFrameCount);
F32 max_bandwidth = gViewerThrottle.getMaxBandwidth();
F32 delta_bandwidth = gViewerThrottle.getCurrentBandwidth() - max_bandwidth;
setStat(LLViewerStats::ST_DELTA_BANDWIDTH, delta_bandwidth / 1024.f);
setStat(ST_DELTA_BANDWIDTH, delta_bandwidth / 1024.f);
setStat(LLViewerStats::ST_MAX_BANDWIDTH, max_bandwidth / 1024.f);
setStat(ST_MAX_BANDWIDTH, max_bandwidth / 1024.f);
}
@ -399,19 +399,6 @@ void LLViewerStats::addToMessage(LLSD &body) const
<< "; Count = " << mAgentPositionSnaps.getCount() << llendl;
}
// static
// const std::string LLViewerStats::statTypeToText(EStatType type)
// {
// if (type >= 0 && type < ST_COUNT)
// {
// return STAT_INFO[type].mName;
// }
// else
// {
// return "Unknown statistic";
// }
// }
// *NOTE:Mani The following methods used to exist in viewer.cpp
// Moving them here, but not merging them into LLViewerStats yet.
void reset_statistics()
@ -579,6 +566,8 @@ void update_statistics(U32 frame_count)
gTotalWorldBytes += gVLManager.getTotalBytes();
gTotalObjectBytes += gObjectBits / 8;
LLViewerStats& stats = LLViewerStats::instance();
// make sure we have a valid time delta for this frame
if (gFrameIntervalSeconds > 0.f)
{
@ -595,42 +584,42 @@ void update_statistics(U32 frame_count)
LLViewerStats::getInstance()->incStat(LLViewerStats::ST_TOOLBOX_SECONDS, gFrameIntervalSeconds);
}
}
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_ENABLE_VBO, (F64)gSavedSettings.getBOOL("RenderVBOEnable"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_LIGHTING_DETAIL, (F64)gPipeline.getLightingDetail());
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_DRAW_DIST, (F64)gSavedSettings.getF32("RenderFarClip"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_CHAT_BUBBLES, (F64)gSavedSettings.getBOOL("UseChatBubbles"));
stats.setStat(LLViewerStats::ST_ENABLE_VBO, (F64)gSavedSettings.getBOOL("RenderVBOEnable"));
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
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_OBJECTS, (F64)gSavedSettings.getS32("VertexShaderLevelObject"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_AVATAR, (F64)gSavedSettings.getBOOL("VertexShaderLevelAvatar"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_SHADER_ENVIRONMENT, (F64)gSavedSettings.getBOOL("VertexShaderLevelEnvironment"));
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
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_FRAME_SECS, gDebugView->mFastTimerView->getTime("Frame"));
stats.setStat(LLViewerStats::ST_FRAME_SECS, gDebugView->mFastTimerView->getTime("Frame"));
F64 idle_secs = gDebugView->mFastTimerView->getTime("Idle");
F64 network_secs = gDebugView->mFastTimerView->getTime("Network");
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_UPDATE_SECS, idle_secs - network_secs);
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_NETWORK_SECS, network_secs);
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_IMAGE_SECS, gDebugView->mFastTimerView->getTime("Update Images"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_REBUILD_SECS, gDebugView->mFastTimerView->getTime("Sort Draw State"));
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_RENDER_SECS, gDebugView->mFastTimerView->getTime("Geometry"));
stats.setStat(LLViewerStats::ST_UPDATE_SECS, idle_secs - network_secs);
stats.setStat(LLViewerStats::ST_NETWORK_SECS, network_secs);
stats.setStat(LLViewerStats::ST_IMAGE_SECS, gDebugView->mFastTimerView->getTime("Update Images"));
stats.setStat(LLViewerStats::ST_REBUILD_SECS, gDebugView->mFastTimerView->getTime("Sort Draw State"));
stats.setStat(LLViewerStats::ST_RENDER_SECS, gDebugView->mFastTimerView->getTime("Geometry"));
LLCircuitData *cdp = gMessageSystem->mCircuitInfo.findCircuit(gAgent.getRegion()->getHost());
if (cdp)
{
LLViewerStats::getInstance()->mSimPingStat.addValue(cdp->getPingDelay());
stats.mSimPingStat.addValue(cdp->getPingDelay());
gAvgSimPing = ((gAvgSimPing * (F32)gSimPingCount) + (F32)(cdp->getPingDelay())) / ((F32)gSimPingCount + 1);
gSimPingCount++;
}
else
{
LLViewerStats::getInstance()->mSimPingStat.addValue(10000);
stats.mSimPingStat.addValue(10000);
}
LLViewerStats::getInstance()->mFPSStat.addValue(1);
stats.mFPSStat.addValue(1);
F32 layer_bits = (F32)(gVLManager.getLandBits() + gVLManager.getWindBits() + gVLManager.getCloudBits());
LLViewerStats::getInstance()->mLayersKBitStat.addValue(layer_bits/1024.f);
LLViewerStats::getInstance()->mObjectKBitStat.addValue(gObjectBits/1024.f);
LLViewerStats::getInstance()->mVFSPendingOperations.addValue(LLVFile::getVFSThread()->getPending());
LLViewerStats::getInstance()->mAssetKBitStat.addValue(gTransferManager.getTransferBitsIn(LLTCT_ASSET)/1024.f);
stats.mLayersKBitStat.addValue(layer_bits/1024.f);
stats.mObjectKBitStat.addValue(gObjectBits/1024.f);
stats.mVFSPendingOperations.addValue(LLVFile::getVFSThread()->getPending());
stats.mAssetKBitStat.addValue(gTransferManager.getTransferBitsIn(LLTCT_ASSET)/1024.f);
gTransferManager.resetTransferBitsIn(LLTCT_ASSET);
if (LLAppViewer::getTextureFetch()->getNumRequests() == 0)
@ -651,7 +640,7 @@ void update_statistics(U32 frame_count)
visible_avatar_frames = 1.f;
avg_visible_avatars = (avg_visible_avatars * (F32)(visible_avatar_frames - 1.f) + visible_avatars) / visible_avatar_frames;
}
LLViewerStats::getInstance()->setStat(LLViewerStats::ST_VISIBLE_AVATARS, (F64)avg_visible_avatars);
stats.setStat(LLViewerStats::ST_VISIBLE_AVATARS, (F64)avg_visible_avatars);
}
LLWorld::getInstance()->updateNetStats();
LLWorld::getInstance()->requestCacheMisses();
@ -667,8 +656,8 @@ void update_statistics(U32 frame_count)
static LLFrameTimer texture_stats_timer;
if (texture_stats_timer.getElapsedTimeF32() >= texture_stats_freq)
{
LLViewerStats::getInstance()->mTextureKBitStat.addValue(LLViewerTextureList::sTextureBits/1024.f);
LLViewerStats::getInstance()->mTexturePacketsStat.addValue(LLViewerTextureList::sTexturePackets);
stats.mTextureKBitStat.addValue(LLViewerTextureList::sTextureBits/1024.f);
stats.mTexturePacketsStat.addValue(LLViewerTextureList::sTexturePackets);
gTotalTextureBytes += LLViewerTextureList::sTextureBits / 8;
LLViewerTextureList::sTextureBits = 0;
LLViewerTextureList::sTexturePackets = 0;

3
indra/newview/llviewerstats.h
View File

@ -112,8 +112,7 @@ public:
void resetStats();
public:
// If you change this, please also add a corresponding text label
// in statTypeToText in llviewerstats.cpp
// If you change this, please also add a corresponding text label in llviewerstats.cpp
enum EStatType
{
ST_VERSION = 0,

181
indra/newview/llviewerstatsrecorder.cpp
View File

@ -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)
S32 total_objects = mObjectCacheHitCount + mObjectCacheMissCrcCount + mObjectCacheMissFullCount + mObjectFullUpdates + mObjectTerseUpdates + mObjectCacheMissRequests + mObjectCacheMissResponses + mObjectCacheUpdateDupes + mObjectCacheUpdateChanges + mObjectCacheUpdateAdds + mObjectCacheUpdateReplacements + mObjectUpdateFailures;
if ( delta_time < interval || total_objects == 0) return;
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;
if (mObjectCacheFile == NULL)
{
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;
if (mObjectCacheFile != NULL &&
total_objects > 0)
{
mStartTime = LLTimer::getTotalSeconds();
mObjectCacheFile = LLFile::fopen(STATS_FILE_NAME, "wb");
if (mObjectCacheFile)
{ // Write column headers
std::ostringstream data_msg;
F32 processing32 = (F32) mProcessingTotalTime;
mProcessingTotalTime = 0.0;
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)
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;
}

67
indra/newview/llviewerstatsrecorder.h
View File

@ -35,7 +35,6 @@
#define LL_RECORD_VIEWER_STATS 1
#if LL_RECORD_VIEWER_STATS
#include "llframetimer.h"
#include "llviewerobject.h"
#include "llviewerregion.h"
@ -50,29 +49,71 @@ class LLViewerStatsRecorder : public LLSingleton<LLViewerStatsRecorder>
LLViewerStatsRecorder();
~LLViewerStatsRecorder();
void beginObjectUpdateEvents(F32 interval);
void objectUpdateFailure(U32 local_id, const EObjectUpdateType update_type, S32 msg_size)
{
#if LL_RECORD_VIEWER_STATS
recordObjectUpdateFailure(local_id, update_type, msg_size);
#endif
}
void cacheMissEvent(U32 local_id, const EObjectUpdateType update_type, U8 cache_miss_type, S32 msg_size)
{
#if LL_RECORD_VIEWER_STATS
recordCacheMissEvent(local_id, update_type, cache_miss_type, msg_size);
#endif
}
void objectUpdateEvent(U32 local_id, const EObjectUpdateType update_type, LLViewerObject * objectp, S32 msg_size)
{
#if LL_RECORD_VIEWER_STATS
recordObjectUpdateEvent(local_id, update_type, objectp, msg_size);
#endif
}
void cacheFullUpdate(U32 local_id, const EObjectUpdateType update_type, LLViewerRegion::eCacheUpdateResult update_result, LLViewerObject* objectp, S32 msg_size)
{
#if LL_RECORD_VIEWER_STATS
recordCacheFullUpdate(local_id, update_type, update_result, objectp, msg_size);
#endif
}
void requestCacheMissesEvent(S32 count)
{
#if LL_RECORD_VIEWER_STATS
recordRequestCacheMissesEvent(count);
#endif
}
void textureFetch(S32 msg_size)
{
#if LL_RECORD_VIEWER_STATS
recordTextureFetch(msg_size);
#endif
}
void log(F32 interval)
{
#if LL_RECORD_VIEWER_STATS
writeToLog(interval);
#endif
}
F32 getTimeSinceStart();
private:
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();
void recordTextureFetch(S32 msg_size);
void writeToLog(F32 interval);
static LLViewerStatsRecorder* sInstance;
LLFILE * mObjectCacheFile; // File to write data into
LLFrameTimer mTimer;
F64 mStartTime;
F64 mProcessingStartTime;
F64 mProcessingTotalTime;
F64 mSnapshotInterval;
F64 mLastSnapshotTime;
S32 mObjectCacheHitCount;
@ -94,11 +135,11 @@ private:
S32 mObjectCacheUpdateReplacements;
S32 mObjectUpdateFailures;
S32 mObjectUpdateFailuresSize;
S32 mTextureFetchSize;
void clearStats();
};
#endif // LL_RECORD_VIEWER_STATS
#endif // LLVIEWERSTATSRECORDER_H