566 lines
17 KiB
C++
566 lines
17 KiB
C++
/*
|
|
|
|
***************************************************************************************************
|
|
**
|
|
** profile.cpp
|
|
**
|
|
** Real-Time Hierarchical Profiling for Game Programming Gems 3
|
|
**
|
|
** by Greg Hjelstrom & Byon Garrabrant
|
|
**
|
|
***************************************************************************************************/
|
|
|
|
// Credits: The Clock class was inspired by the Timer classes in
|
|
// Ogre (www.ogre3d.org).
|
|
|
|
#include "btQuickprof.h"
|
|
|
|
#ifndef BT_NO_PROFILE
|
|
|
|
|
|
static btClock gProfileClock;
|
|
|
|
|
|
#ifdef __CELLOS_LV2__
|
|
#include <sys/sys_time.h>
|
|
#include <sys/time_util.h>
|
|
#include <stdio.h>
|
|
#endif
|
|
|
|
#if defined (SUNOS) || defined (__SUNOS__)
|
|
#include <stdio.h>
|
|
#endif
|
|
|
|
#if defined(WIN32) || defined(_WIN32)
|
|
|
|
#define BT_USE_WINDOWS_TIMERS
|
|
#define WIN32_LEAN_AND_MEAN
|
|
#define NOWINRES
|
|
#define NOMCX
|
|
#define NOIME
|
|
|
|
#ifdef _XBOX
|
|
#include <Xtl.h>
|
|
#else //_XBOX
|
|
#include <windows.h>
|
|
#endif //_XBOX
|
|
|
|
#include <time.h>
|
|
|
|
|
|
#else //_WIN32
|
|
#include <sys/time.h>
|
|
#endif //_WIN32
|
|
|
|
#define mymin(a,b) (a > b ? a : b)
|
|
|
|
struct btClockData
|
|
{
|
|
|
|
#ifdef BT_USE_WINDOWS_TIMERS
|
|
LARGE_INTEGER mClockFrequency;
|
|
DWORD mStartTick;
|
|
LONGLONG mPrevElapsedTime;
|
|
LARGE_INTEGER mStartTime;
|
|
#else
|
|
#ifdef __CELLOS_LV2__
|
|
uint64_t mStartTime;
|
|
#else
|
|
struct timeval mStartTime;
|
|
#endif
|
|
#endif //__CELLOS_LV2__
|
|
|
|
};
|
|
|
|
///The btClock is a portable basic clock that measures accurate time in seconds, use for profiling.
|
|
btClock::btClock()
|
|
{
|
|
m_data = new btClockData;
|
|
#ifdef BT_USE_WINDOWS_TIMERS
|
|
QueryPerformanceFrequency(&m_data->mClockFrequency);
|
|
#endif
|
|
reset();
|
|
}
|
|
|
|
btClock::~btClock()
|
|
{
|
|
delete m_data;
|
|
}
|
|
|
|
btClock::btClock(const btClock& other)
|
|
{
|
|
m_data = new btClockData;
|
|
*m_data = *other.m_data;
|
|
}
|
|
|
|
btClock& btClock::operator=(const btClock& other)
|
|
{
|
|
*m_data = *other.m_data;
|
|
return *this;
|
|
}
|
|
|
|
|
|
/// Resets the initial reference time.
|
|
void btClock::reset()
|
|
{
|
|
#ifdef BT_USE_WINDOWS_TIMERS
|
|
QueryPerformanceCounter(&m_data->mStartTime);
|
|
m_data->mStartTick = GetTickCount();
|
|
m_data->mPrevElapsedTime = 0;
|
|
#else
|
|
#ifdef __CELLOS_LV2__
|
|
|
|
typedef uint64_t ClockSize;
|
|
ClockSize newTime;
|
|
//__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
|
|
SYS_TIMEBASE_GET( newTime );
|
|
m_data->mStartTime = newTime;
|
|
#else
|
|
gettimeofday(&m_data->mStartTime, 0);
|
|
#endif
|
|
#endif
|
|
}
|
|
|
|
/// Returns the time in ms since the last call to reset or since
|
|
/// the btClock was created.
|
|
unsigned long int btClock::getTimeMilliseconds()
|
|
{
|
|
#ifdef BT_USE_WINDOWS_TIMERS
|
|
LARGE_INTEGER currentTime;
|
|
QueryPerformanceCounter(¤tTime);
|
|
LONGLONG elapsedTime = currentTime.QuadPart -
|
|
m_data->mStartTime.QuadPart;
|
|
// Compute the number of millisecond ticks elapsed.
|
|
unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
|
|
m_data->mClockFrequency.QuadPart);
|
|
// Check for unexpected leaps in the Win32 performance counter.
|
|
// (This is caused by unexpected data across the PCI to ISA
|
|
// bridge, aka south bridge. See Microsoft KB274323.)
|
|
unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
|
|
signed long msecOff = (signed long)(msecTicks - elapsedTicks);
|
|
if (msecOff < -100 || msecOff > 100)
|
|
{
|
|
// Adjust the starting time forwards.
|
|
LONGLONG msecAdjustment = mymin(msecOff *
|
|
m_data->mClockFrequency.QuadPart / 1000, elapsedTime -
|
|
m_data->mPrevElapsedTime);
|
|
m_data->mStartTime.QuadPart += msecAdjustment;
|
|
elapsedTime -= msecAdjustment;
|
|
|
|
// Recompute the number of millisecond ticks elapsed.
|
|
msecTicks = (unsigned long)(1000 * elapsedTime /
|
|
m_data->mClockFrequency.QuadPart);
|
|
}
|
|
|
|
// Store the current elapsed time for adjustments next time.
|
|
m_data->mPrevElapsedTime = elapsedTime;
|
|
|
|
return msecTicks;
|
|
#else
|
|
|
|
#ifdef __CELLOS_LV2__
|
|
uint64_t freq=sys_time_get_timebase_frequency();
|
|
double dFreq=((double) freq) / 1000.0;
|
|
typedef uint64_t ClockSize;
|
|
ClockSize newTime;
|
|
SYS_TIMEBASE_GET( newTime );
|
|
//__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
|
|
|
|
return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
|
|
#else
|
|
|
|
struct timeval currentTime;
|
|
gettimeofday(¤tTime, 0);
|
|
return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000 +
|
|
(currentTime.tv_usec - m_data->mStartTime.tv_usec) / 1000;
|
|
#endif //__CELLOS_LV2__
|
|
#endif
|
|
}
|
|
|
|
/// Returns the time in us since the last call to reset or since
|
|
/// the Clock was created.
|
|
unsigned long int btClock::getTimeMicroseconds()
|
|
{
|
|
#ifdef BT_USE_WINDOWS_TIMERS
|
|
LARGE_INTEGER currentTime;
|
|
QueryPerformanceCounter(¤tTime);
|
|
LONGLONG elapsedTime = currentTime.QuadPart -
|
|
m_data->mStartTime.QuadPart;
|
|
|
|
// Compute the number of millisecond ticks elapsed.
|
|
unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
|
|
m_data->mClockFrequency.QuadPart);
|
|
|
|
// Check for unexpected leaps in the Win32 performance counter.
|
|
// (This is caused by unexpected data across the PCI to ISA
|
|
// bridge, aka south bridge. See Microsoft KB274323.)
|
|
unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
|
|
signed long msecOff = (signed long)(msecTicks - elapsedTicks);
|
|
if (msecOff < -100 || msecOff > 100)
|
|
{
|
|
// Adjust the starting time forwards.
|
|
LONGLONG msecAdjustment = mymin(msecOff *
|
|
m_data->mClockFrequency.QuadPart / 1000, elapsedTime -
|
|
m_data->mPrevElapsedTime);
|
|
m_data->mStartTime.QuadPart += msecAdjustment;
|
|
elapsedTime -= msecAdjustment;
|
|
}
|
|
|
|
// Store the current elapsed time for adjustments next time.
|
|
m_data->mPrevElapsedTime = elapsedTime;
|
|
|
|
// Convert to microseconds.
|
|
unsigned long usecTicks = (unsigned long)(1000000 * elapsedTime /
|
|
m_data->mClockFrequency.QuadPart);
|
|
|
|
return usecTicks;
|
|
#else
|
|
|
|
#ifdef __CELLOS_LV2__
|
|
uint64_t freq=sys_time_get_timebase_frequency();
|
|
double dFreq=((double) freq)/ 1000000.0;
|
|
typedef uint64_t ClockSize;
|
|
ClockSize newTime;
|
|
//__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
|
|
SYS_TIMEBASE_GET( newTime );
|
|
|
|
return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
|
|
#else
|
|
|
|
struct timeval currentTime;
|
|
gettimeofday(¤tTime, 0);
|
|
return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000000 +
|
|
(currentTime.tv_usec - m_data->mStartTime.tv_usec);
|
|
#endif//__CELLOS_LV2__
|
|
#endif
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
inline void Profile_Get_Ticks(unsigned long int * ticks)
|
|
{
|
|
*ticks = gProfileClock.getTimeMicroseconds();
|
|
}
|
|
|
|
inline float Profile_Get_Tick_Rate(void)
|
|
{
|
|
// return 1000000.f;
|
|
return 1000.f;
|
|
|
|
}
|
|
|
|
|
|
|
|
/***************************************************************************************************
|
|
**
|
|
** CProfileNode
|
|
**
|
|
***************************************************************************************************/
|
|
|
|
/***********************************************************************************************
|
|
* INPUT: *
|
|
* name - pointer to a static string which is the name of this profile node *
|
|
* parent - parent pointer *
|
|
* *
|
|
* WARNINGS: *
|
|
* The name is assumed to be a static pointer, only the pointer is stored and compared for *
|
|
* efficiency reasons. *
|
|
*=============================================================================================*/
|
|
CProfileNode::CProfileNode( const char * name, CProfileNode * parent ) :
|
|
Name( name ),
|
|
TotalCalls( 0 ),
|
|
TotalTime( 0 ),
|
|
StartTime( 0 ),
|
|
RecursionCounter( 0 ),
|
|
Parent( parent ),
|
|
Child( NULL ),
|
|
Sibling( NULL )
|
|
{
|
|
Reset();
|
|
}
|
|
|
|
|
|
void CProfileNode::CleanupMemory()
|
|
{
|
|
delete ( Child);
|
|
Child = NULL;
|
|
delete ( Sibling);
|
|
Sibling = NULL;
|
|
}
|
|
|
|
CProfileNode::~CProfileNode( void )
|
|
{
|
|
delete ( Child);
|
|
delete ( Sibling);
|
|
}
|
|
|
|
|
|
/***********************************************************************************************
|
|
* INPUT: *
|
|
* name - static string pointer to the name of the node we are searching for *
|
|
* *
|
|
* WARNINGS: *
|
|
* All profile names are assumed to be static strings so this function uses pointer compares *
|
|
* to find the named node. *
|
|
*=============================================================================================*/
|
|
CProfileNode * CProfileNode::Get_Sub_Node( const char * name )
|
|
{
|
|
// Try to find this sub node
|
|
CProfileNode * child = Child;
|
|
while ( child ) {
|
|
if ( child->Name == name ) {
|
|
return child;
|
|
}
|
|
child = child->Sibling;
|
|
}
|
|
|
|
// We didn't find it, so add it
|
|
|
|
CProfileNode * node = new CProfileNode( name, this );
|
|
node->Sibling = Child;
|
|
Child = node;
|
|
return node;
|
|
}
|
|
|
|
|
|
void CProfileNode::Reset( void )
|
|
{
|
|
TotalCalls = 0;
|
|
TotalTime = 0.0f;
|
|
|
|
|
|
if ( Child ) {
|
|
Child->Reset();
|
|
}
|
|
if ( Sibling ) {
|
|
Sibling->Reset();
|
|
}
|
|
}
|
|
|
|
|
|
void CProfileNode::Call( void )
|
|
{
|
|
TotalCalls++;
|
|
if (RecursionCounter++ == 0) {
|
|
Profile_Get_Ticks(&StartTime);
|
|
}
|
|
}
|
|
|
|
|
|
bool CProfileNode::Return( void )
|
|
{
|
|
if ( --RecursionCounter == 0 && TotalCalls != 0 ) {
|
|
unsigned long int time;
|
|
Profile_Get_Ticks(&time);
|
|
time-=StartTime;
|
|
TotalTime += (float)time / Profile_Get_Tick_Rate();
|
|
}
|
|
return ( RecursionCounter == 0 );
|
|
}
|
|
|
|
|
|
/***************************************************************************************************
|
|
**
|
|
** CProfileIterator
|
|
**
|
|
***************************************************************************************************/
|
|
CProfileIterator::CProfileIterator( CProfileNode * start )
|
|
{
|
|
CurrentParent = start;
|
|
CurrentChild = CurrentParent->Get_Child();
|
|
}
|
|
|
|
|
|
void CProfileIterator::First(void)
|
|
{
|
|
CurrentChild = CurrentParent->Get_Child();
|
|
}
|
|
|
|
|
|
void CProfileIterator::Next(void)
|
|
{
|
|
CurrentChild = CurrentChild->Get_Sibling();
|
|
}
|
|
|
|
|
|
bool CProfileIterator::Is_Done(void)
|
|
{
|
|
return CurrentChild == NULL;
|
|
}
|
|
|
|
|
|
void CProfileIterator::Enter_Child( int index )
|
|
{
|
|
CurrentChild = CurrentParent->Get_Child();
|
|
while ( (CurrentChild != NULL) && (index != 0) ) {
|
|
index--;
|
|
CurrentChild = CurrentChild->Get_Sibling();
|
|
}
|
|
|
|
if ( CurrentChild != NULL ) {
|
|
CurrentParent = CurrentChild;
|
|
CurrentChild = CurrentParent->Get_Child();
|
|
}
|
|
}
|
|
|
|
|
|
void CProfileIterator::Enter_Parent( void )
|
|
{
|
|
if ( CurrentParent->Get_Parent() != NULL ) {
|
|
CurrentParent = CurrentParent->Get_Parent();
|
|
}
|
|
CurrentChild = CurrentParent->Get_Child();
|
|
}
|
|
|
|
|
|
/***************************************************************************************************
|
|
**
|
|
** CProfileManager
|
|
**
|
|
***************************************************************************************************/
|
|
|
|
CProfileNode CProfileManager::Root( "Root", NULL );
|
|
CProfileNode * CProfileManager::CurrentNode = &CProfileManager::Root;
|
|
int CProfileManager::FrameCounter = 0;
|
|
unsigned long int CProfileManager::ResetTime = 0;
|
|
|
|
|
|
/***********************************************************************************************
|
|
* CProfileManager::Start_Profile -- Begin a named profile *
|
|
* *
|
|
* Steps one level deeper into the tree, if a child already exists with the specified name *
|
|
* then it accumulates the profiling; otherwise a new child node is added to the profile tree. *
|
|
* *
|
|
* INPUT: *
|
|
* name - name of this profiling record *
|
|
* *
|
|
* WARNINGS: *
|
|
* The string used is assumed to be a static string; pointer compares are used throughout *
|
|
* the profiling code for efficiency. *
|
|
*=============================================================================================*/
|
|
void CProfileManager::Start_Profile( const char * name )
|
|
{
|
|
if (name != CurrentNode->Get_Name()) {
|
|
CurrentNode = CurrentNode->Get_Sub_Node( name );
|
|
}
|
|
|
|
CurrentNode->Call();
|
|
}
|
|
|
|
|
|
/***********************************************************************************************
|
|
* CProfileManager::Stop_Profile -- Stop timing and record the results. *
|
|
*=============================================================================================*/
|
|
void CProfileManager::Stop_Profile( void )
|
|
{
|
|
// Return will indicate whether we should back up to our parent (we may
|
|
// be profiling a recursive function)
|
|
if (CurrentNode->Return()) {
|
|
CurrentNode = CurrentNode->Get_Parent();
|
|
}
|
|
}
|
|
|
|
|
|
/***********************************************************************************************
|
|
* CProfileManager::Reset -- Reset the contents of the profiling system *
|
|
* *
|
|
* This resets everything except for the tree structure. All of the timing data is reset. *
|
|
*=============================================================================================*/
|
|
void CProfileManager::Reset( void )
|
|
{
|
|
gProfileClock.reset();
|
|
Root.Reset();
|
|
Root.Call();
|
|
FrameCounter = 0;
|
|
Profile_Get_Ticks(&ResetTime);
|
|
}
|
|
|
|
|
|
/***********************************************************************************************
|
|
* CProfileManager::Increment_Frame_Counter -- Increment the frame counter *
|
|
*=============================================================================================*/
|
|
void CProfileManager::Increment_Frame_Counter( void )
|
|
{
|
|
FrameCounter++;
|
|
}
|
|
|
|
|
|
/***********************************************************************************************
|
|
* CProfileManager::Get_Time_Since_Reset -- returns the elapsed time since last reset *
|
|
*=============================================================================================*/
|
|
float CProfileManager::Get_Time_Since_Reset( void )
|
|
{
|
|
unsigned long int time;
|
|
Profile_Get_Ticks(&time);
|
|
time -= ResetTime;
|
|
return (float)time / Profile_Get_Tick_Rate();
|
|
}
|
|
|
|
#include <stdio.h>
|
|
|
|
void CProfileManager::dumpRecursive(CProfileIterator* profileIterator, int spacing)
|
|
{
|
|
profileIterator->First();
|
|
if (profileIterator->Is_Done())
|
|
return;
|
|
|
|
float accumulated_time=0,parent_time = profileIterator->Is_Root() ? CProfileManager::Get_Time_Since_Reset() : profileIterator->Get_Current_Parent_Total_Time();
|
|
int i;
|
|
int frames_since_reset = CProfileManager::Get_Frame_Count_Since_Reset();
|
|
for (i=0;i<spacing;i++) printf(".");
|
|
printf("----------------------------------\n");
|
|
for (i=0;i<spacing;i++) printf(".");
|
|
printf("Profiling: %s (total running time: %.3f ms) ---\n", profileIterator->Get_Current_Parent_Name(), parent_time );
|
|
float totalTime = 0.f;
|
|
|
|
|
|
int numChildren = 0;
|
|
|
|
for (i = 0; !profileIterator->Is_Done(); i++,profileIterator->Next())
|
|
{
|
|
numChildren++;
|
|
float current_total_time = profileIterator->Get_Current_Total_Time();
|
|
accumulated_time += current_total_time;
|
|
float fraction = parent_time > SIMD_EPSILON ? (current_total_time / parent_time) * 100 : 0.f;
|
|
{
|
|
int i; for (i=0;i<spacing;i++) printf(".");
|
|
}
|
|
printf("%d -- %s (%.2f %%) :: %.3f ms / frame (%d calls)\n",i, profileIterator->Get_Current_Name(), fraction,(current_total_time / (double)frames_since_reset),profileIterator->Get_Current_Total_Calls());
|
|
totalTime += current_total_time;
|
|
//recurse into children
|
|
}
|
|
|
|
if (parent_time < accumulated_time)
|
|
{
|
|
printf("what's wrong\n");
|
|
}
|
|
for (i=0;i<spacing;i++) printf(".");
|
|
printf("%s (%.3f %%) :: %.3f ms\n", "Unaccounted:",parent_time > SIMD_EPSILON ? ((parent_time - accumulated_time) / parent_time) * 100 : 0.f, parent_time - accumulated_time);
|
|
|
|
for (i=0;i<numChildren;i++)
|
|
{
|
|
profileIterator->Enter_Child(i);
|
|
dumpRecursive(profileIterator,spacing+3);
|
|
profileIterator->Enter_Parent();
|
|
}
|
|
}
|
|
|
|
|
|
|
|
void CProfileManager::dumpAll()
|
|
{
|
|
CProfileIterator* profileIterator = 0;
|
|
profileIterator = CProfileManager::Get_Iterator();
|
|
|
|
dumpRecursive(profileIterator,0);
|
|
|
|
CProfileManager::Release_Iterator(profileIterator);
|
|
}
|
|
|
|
|
|
|
|
|
|
#endif //BT_NO_PROFILE
|