quake4-sdk/source/idlib/TimingCollection.cpp

#include "precompiled.h"
#pragma hdrstop

#if !defined(__TIMINGCOLLECTION_H_)
	#include "TimingCollection.h"
#endif

#ifdef RV_TIMERCOLLECTION

//-----------------------------------------------------------------------------
//
//								rvSingleTiming::Clear
//
//-----------------------------------------------------------------------------

void rvSingleTiming::Clear( void )
{
	mTotalUpdates			= 0;
	mCurValue				= 0;
	mTotalValue				= 0;
	mPeakValue				= 0;
	mLimit					= 0;
	mLimitExceeded			= 0;
	mLimitExceededTimesFive	= 0;
	mDisplayLevel			= 0;
	mName					= "";
	mParentName				= "";

	mStartFile				= "";
	mStartLine				= 0;
	mEndFile				= "";
	mEndLine				= 0;
}

//-----------------------------------------------------------------------------
//
//								rvSingleTiming::rvSingleTiming
//
//-----------------------------------------------------------------------------

rvSingleTiming::rvSingleTiming()
{
	Clear();
}

//-----------------------------------------------------------------------------
//
//								rvSingleTiming::rvSingleTiming
//
//-----------------------------------------------------------------------------

rvSingleTiming::rvSingleTiming( idStr &newName )
{
	Clear();
	mName = newName;
}

//-----------------------------------------------------------------------------
//
//								rvSingleTiming::OutputDataToFile
//
//-----------------------------------------------------------------------------

void rvSingleTiming::OutputDataToFile( idFile *file, int framesRecorded )
{
	char	buffer[1024];
	idStr	outputName = "";

	for( int i = 0; i < mDisplayLevel; i++ )
	{
		outputName += "**";
	}
	outputName += mName;

	sprintf(buffer, "%-36s %-9.3f %-9.3f %-9.3f %-9.3f %-9i %-9i %-9.3f\n", outputName.c_str(), 
		(float)mTotalValue, (float)( mTotalValue / (float)framesRecorded), (float)mPeakValue,
		(float)mLimit, mLimitExceeded, mLimitExceededTimesFive, (float)(mTotalUpdates / (float)framesRecorded) );
	file->Write ( buffer, strlen( buffer ) );
}

//-----------------------------------------------------------------------------
//
//								rvSingleTiming::OutputInfoToFile
//
//-----------------------------------------------------------------------------

void rvSingleTiming::OutputInfoToFile( idFile *file )
{
	char	buffer[1024];

	sprintf(buffer, "Name: %s\nParent: %s\n", mName.c_str(), mParentName.c_str() );
	file->Write ( buffer, strlen( buffer ) );

	sprintf(buffer, "Starting at %s(%d)\nEnding at %s(%d)\n\n", mStartFile.c_str(), mStartLine, mEndFile.c_str(), mEndLine );
	file->Write ( buffer, strlen( buffer ) );
}














//-----------------------------------------------------------------------------
//
//								rvTimingCollection::Clear
//
//-----------------------------------------------------------------------------

void rvTimingCollection::Clear( void )
{
	mUpdates			= 0;
	mCurTimer			= 0;
	mFramesRecorded		= 0;
	mCurrentlyUpdating	= 0;
	mTimings.Clear();
	mTimingsIndex.Clear();
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::rvTimingCollection
//
//-----------------------------------------------------------------------------

rvTimingCollection::rvTimingCollection()
{
	Clear();
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::GetTiming
//
//-----------------------------------------------------------------------------

rvSingleTiming *rvTimingCollection::GetTiming( idStr &timingName )
{
	int *handle = NULL;

	if( mTimingsIndex.Get( timingName, &handle ) ) 
	{	
		return( &mTimings[*handle] );
	}

	rvSingleTiming	newTiming( timingName );
	int				index = mTimings.Num();
	
	mTimingsIndex.Set( timingName, index );
	mTimings.Append( newTiming );
	return &mTimings[index];
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::DisplayTimingValues
//
//-----------------------------------------------------------------------------

void rvTimingCollection::DisplayTimingValues( void ) {
	// Fixme: the display resulting from this is really, really a mess - quite unreadable.
	common->Printf ( "Timer: \n" );
	for( int i = 0; i < mTimings.Num(); i++ ) {
		if ( (int)(mTimings[i].mCurValue) ) {
			common->Printf( "\t%s %3i\n", mTimings[i].mName.c_str(), (int)(mTimings[i].mCurValue) );
		}
	}
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::OutputToFile
//
//-----------------------------------------------------------------------------

void rvTimingCollection::OutputToFile( void )
{
	idFile	*file	= NULL;
	idStr	name;
	char	buffer[1024];

	// Fixme: Do we have any good information for building a better file name here?

	name = "Timings/output.txt";

	file = fileSystem->OpenFileWrite ( name );
	if ( !file )
	{
		return;
	}

	sprintf( buffer, "Total frames = %d\n\n", mFramesRecorded );
	file->Write( buffer, strlen( buffer ) );

	sprintf( buffer, "%-36s %-9s %-9s %-9s %-9s %-9s %-9s %-9s\n\n",
		"Name", "Total", "Average", "Peak", "Limit", "Exceeded", "Exceed*5", "Calls" );
	file->Write ( buffer, strlen( buffer ) );

	for( int i = 0; i < mTimings.Num(); i++ )
	{
		mTimings[i].OutputDataToFile( file, mFramesRecorded );
		if( !( ( i + 1 )%3) )	// break up the prints into groups of 3 to make scanning visually easier.
		{
			sprintf( buffer, "\n" );
			file->Write( buffer, strlen( buffer ) );
		}
	}

	sprintf(buffer, "\n\nInformation about categories\n\n" );
	file->Write ( buffer, strlen( buffer ) );

	for( int i = 0; i < mTimings.Num(); i++ )
	{
		mTimings[i].OutputInfoToFile( file );
	}

	fileSystem->CloseFile ( file );
	file = NULL;
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::AppendToDict
//
//-----------------------------------------------------------------------------

void rvTimingCollection::AppendToDict( idDict *dict )
{
	if( !mCurrentlyUpdating )
	{
		return;
	}

	for( int i = 0; i < mTimings.Num(); i++ )
	{
		dict->Set ( mTimings[i].mName.c_str(), va( "%0.3g\t%0.3g\t", mTimings[i].mCurValue, mTimings[i].mTotalValue ) );
	}
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::InitFrame
//
//-----------------------------------------------------------------------------

void rvTimingCollection::InitFrame( bool inUse, bool displayText, bool outputFileWhenDone )
{
	// Do our quick reject test to ensure this is quick when not in use.

	if( !inUse )
	{
		if( mCurrentlyUpdating )
		{
			if( outputFileWhenDone )
			{
				OutputToFile();
			}
			mCurrentlyUpdating = 0;
		}
		return;
	}

	mCurrentlyUpdating = 1;
	mUpdates++;
	mFramesRecorded++;

	if( mUpdates >= 10 && displayText )
	{
		// ??  If we display output every single frame, we get REALLY bogged down.  It is bad.

		DisplayTimingValues();

		mUpdates = 0;

		return;
	}

	// Clear only the curValues and record information.

	for( int i = 0; i < mTimings.Num(); i++ )
	{
		if( mTimings[i].mCurValue > mTimings[i].mPeakValue )
		{
			mTimings[i].mPeakValue = mTimings[i].mCurValue;
		}

		if( mTimings[i].mLimit > 0.0 && mTimings[i].mCurValue > mTimings[i].mLimit )
		{
			mTimings[i].mLimitExceeded++;
		}

		if( mTimings[i].mLimit > 0.0 && mTimings[i].mCurValue > mTimings[i].mLimit * 5 )
		{
			mTimings[i].mLimitExceededTimesFive++;
		}

		mTimings[i].mCurValue = 0.0f;
	}
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::TimingStart
//
//-----------------------------------------------------------------------------

void rvTimingCollection::_TimingStart( const char *timingName, const char *fileName, const int lineNum )
{
	// Do our quick reject test to ensure this is quick when not in use.

	if( !mCurrentlyUpdating )
	{
		return;
	}

	// Go up the timer list.

	mCurTimer++; 
	assert( mCurTimer < MAX_TIMERS );

	// Keep track of the current function being timed in case we nest and need to know our parent.

	mTimerName[mCurTimer] = timingName;

	// Set the information about this timer.

	rvSingleTiming *curTiming = GetTiming( mTimerName[mCurTimer] );
	
	if( mCurTimer == 0 )
	{
		curTiming->mParentName = "base";
	}
	else
	{
		curTiming->mParentName = mTimerName[mCurTimer - 1];
	}
	curTiming->mStartFile		= fileName;
	curTiming->mStartLine		= lineNum;
	curTiming->mDisplayLevel	= mCurTimer - 1;

	// Start the timer; do it last to avoid timing the rest of this function.

	mTimer[mCurTimer].Clear();
	mTimer[mCurTimer].Start();
}

//-----------------------------------------------------------------------------
//
//								rvTimingCollection::TimingEnd
//
//-----------------------------------------------------------------------------

void rvTimingCollection::_TimingStop( double msecLimit, const char *fileName, const int lineNum )
{
	// Do our quick reject test to ensure this is quick when not in use.

	if( !mCurrentlyUpdating )
	{
		return;
	}

	// Stop our timer first so that we don't log time from the rest of this function.

	mTimer[mCurTimer].Stop();

	// Update incidental information on the timer.

	rvSingleTiming *curTiming = GetTiming( mTimerName[mCurTimer] );
	
	curTiming->mEndFile = fileName;
	curTiming->mEndLine = lineNum;

	curTiming->mLimit	= msecLimit;

	// Add the actual timing values to the rvSingleTiming

	double	frameTime = mTimer[mCurTimer].Milliseconds();

	curTiming->mCurValue	+= frameTime;
	curTiming->mTotalValue	+= frameTime;

	curTiming->mTotalUpdates++;

	// Go back down the timer list.

	mCurTimer--;
	assert( mCurTimer >= 0 );
}

#endif