Example Browser: add option (keypress 'p') to dump json timing profile trace, that you can open using Chrome about://tracing

Make btQuickprof thread safe
Add option in btQuickprof to override custom timing profile (btSetCustomEnterProfileZoneFunc, btSetCustomLeaveProfileZoneFunc)
remove b3Printf in a user/physics thread (those added added, while drawing the GUI running in the main thread)
This commit is contained in:
Erwin Coumans
2016-12-23 15:20:04 -08:00
parent da7ae53941
commit 4c06fd27b3
12 changed files with 515 additions and 225 deletions

View File

@@ -16,9 +16,7 @@
#include "btQuickprof.h"
#if BT_THREADSAFE
#include "btThreads.h"
#endif //#if BT_THREADSAFE
#ifdef __CELLOS_LV2__
@@ -65,7 +63,6 @@ struct btClockData
#ifdef BT_USE_WINDOWS_TIMERS
LARGE_INTEGER mClockFrequency;
LONGLONG mStartTick;
LONGLONG mPrevElapsedTime;
LARGE_INTEGER mStartTime;
#else
#ifdef __CELLOS_LV2__
@@ -111,7 +108,6 @@ void btClock::reset()
#ifdef BT_USE_WINDOWS_TIMERS
QueryPerformanceCounter(&m_data->mStartTime);
m_data->mStartTick = GetTickCount64();
m_data->mPrevElapsedTime = 0;
#else
#ifdef __CELLOS_LV2__
@@ -128,7 +124,7 @@ void btClock::reset()
/// Returns the time in ms since the last call to reset or since
/// the btClock was created.
unsigned long int btClock::getTimeMilliseconds()
unsigned long long int btClock::getTimeMilliseconds()
{
#ifdef BT_USE_WINDOWS_TIMERS
LARGE_INTEGER currentTime;
@@ -138,27 +134,6 @@ unsigned long int btClock::getTimeMilliseconds()
// 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 = (unsigned long)(GetTickCount64() - 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
@@ -184,41 +159,19 @@ unsigned long int btClock::getTimeMilliseconds()
/// Returns the time in us since the last call to reset or since
/// the Clock was created.
unsigned long int btClock::getTimeMicroseconds()
unsigned long long int btClock::getTimeMicroseconds()
{
#ifdef BT_USE_WINDOWS_TIMERS
LARGE_INTEGER currentTime;
//see https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx
LARGE_INTEGER currentTime, elapsedTime;
QueryPerformanceCounter(&currentTime);
LONGLONG elapsedTime = currentTime.QuadPart -
elapsedTime.QuadPart = currentTime.QuadPart -
m_data->mStartTime.QuadPart;
elapsedTime.QuadPart *= 1000000;
elapsedTime.QuadPart /= m_data->mClockFrequency.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 = (unsigned long)(GetTickCount64() - 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;
return (unsigned long long) elapsedTime.QuadPart;
#else
#ifdef __CELLOS_LV2__
@@ -240,6 +193,39 @@ unsigned long int btClock::getTimeMicroseconds()
#endif
}
unsigned long long int btClock::getTimeNanoseconds()
{
#ifdef BT_USE_WINDOWS_TIMERS
//see https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx
LARGE_INTEGER currentTime, elapsedTime;
QueryPerformanceCounter(&currentTime);
elapsedTime.QuadPart = currentTime.QuadPart -
m_data->mStartTime.QuadPart;
elapsedTime.QuadPart *= 1e9;
elapsedTime.QuadPart /= m_data->mClockFrequency.QuadPart;
return (unsigned long long) elapsedTime.QuadPart;
#else
#ifdef __CELLOS_LV2__
uint64_t freq=sys_time_get_timebase_frequency();
double dFreq=((double) freq)/ 1e9;
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(&currentTime, 0);
return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1e9 +
(currentTime.tv_usec - m_data->mStartTime.tv_usec);
#endif//__CELLOS_LV2__
#endif
}
/// Returns the time in s since the last call to reset or since
@@ -370,6 +356,7 @@ 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();
}
@@ -437,11 +424,69 @@ void CProfileIterator::Enter_Parent( void )
**
***************************************************************************************************/
CProfileNode CProfileManager::Root( "Root", NULL );
CProfileNode * CProfileManager::CurrentNode = &CProfileManager::Root;
#include "btThreads.h"
CProfileNode gRoots[BT_MAX_THREAD_COUNT]={
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),
CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL),CProfileNode("Root",NULL)
};
CProfileNode* gCurrentNodes[BT_MAX_THREAD_COUNT]=
{
&gRoots[ 0], &gRoots[ 1], &gRoots[ 2], &gRoots[ 3],
&gRoots[ 4], &gRoots[ 5], &gRoots[ 6], &gRoots[ 7],
&gRoots[ 8], &gRoots[ 9], &gRoots[10], &gRoots[11],
&gRoots[12], &gRoots[13], &gRoots[14], &gRoots[15],
&gRoots[16], &gRoots[17], &gRoots[18], &gRoots[19],
&gRoots[20], &gRoots[21], &gRoots[22], &gRoots[23],
&gRoots[24], &gRoots[25], &gRoots[26], &gRoots[27],
&gRoots[28], &gRoots[29], &gRoots[30], &gRoots[31],
&gRoots[32], &gRoots[33], &gRoots[34], &gRoots[35],
&gRoots[36], &gRoots[37], &gRoots[38], &gRoots[39],
&gRoots[40], &gRoots[41], &gRoots[42], &gRoots[43],
&gRoots[44], &gRoots[45], &gRoots[46], &gRoots[47],
&gRoots[48], &gRoots[49], &gRoots[50], &gRoots[51],
&gRoots[52], &gRoots[53], &gRoots[54], &gRoots[55],
&gRoots[56], &gRoots[57], &gRoots[58], &gRoots[59],
&gRoots[60], &gRoots[61], &gRoots[62], &gRoots[63],
};
int CProfileManager::FrameCounter = 0;
unsigned long int CProfileManager::ResetTime = 0;
CProfileIterator * CProfileManager::Get_Iterator( void )
{
int threadIndex = btGetCurrentThreadIndex();
return new CProfileIterator( &gRoots[threadIndex]);
}
void CProfileManager::CleanupMemory(void)
{
for (int i=0;i<BT_MAX_THREAD_COUNT;i++)
{
gRoots[i].CleanupMemory();
}
}
/***********************************************************************************************
* CProfileManager::Start_Profile -- Begin a named profile *
@@ -458,19 +503,12 @@ unsigned long int CProfileManager::ResetTime = 0;
*=============================================================================================*/
void CProfileManager::Start_Profile( const char * name )
{
#if BT_THREADSAFE
// profile system is not designed for profiling multiple threads
// disable collection on all but the main thread
if ( !btIsMainThread() )
{
return;
}
#endif //#if BT_THREADSAFE
if (name != CurrentNode->Get_Name()) {
CurrentNode = CurrentNode->Get_Sub_Node( name );
int threadIndex = btGetCurrentThreadIndex();
if (name != gCurrentNodes[threadIndex]->Get_Name()) {
gCurrentNodes[threadIndex] = gCurrentNodes[threadIndex]->Get_Sub_Node( name );
}
CurrentNode->Call();
gCurrentNodes[threadIndex]->Call();
}
@@ -479,22 +517,26 @@ void CProfileManager::Start_Profile( const char * name )
*=============================================================================================*/
void CProfileManager::Stop_Profile( void )
{
#if BT_THREADSAFE
// profile system is not designed for profiling multiple threads
// disable collection on all but the main thread
if ( !btIsMainThread() )
{
return;
}
#endif //#if BT_THREADSAFE
int threadIndex = btGetCurrentThreadIndex();
// 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();
if (gCurrentNodes[threadIndex]->Return()) {
gCurrentNodes[threadIndex] = gCurrentNodes[threadIndex]->Get_Parent();
}
}
void btEnterProfileZoneDefault(const char* name)
{
CProfileManager::Start_Profile( name );
}
void btLeaveProfileZoneDefault()
{
CProfileManager::Stop_Profile();
}
/***********************************************************************************************
* CProfileManager::Reset -- Reset the contents of the profiling system *
* *
@@ -503,8 +545,8 @@ void CProfileManager::Stop_Profile( void )
void CProfileManager::Reset( void )
{
gProfileClock.reset();
Root.Reset();
Root.Call();
gRoots[btGetCurrentThreadIndex()].Reset();
gRoots[btGetCurrentThreadIndex()].Call();
FrameCounter = 0;
Profile_Get_Ticks(&ResetTime);
}
@@ -592,6 +634,56 @@ void CProfileManager::dumpAll()
}
#else
void btEnterProfileZoneDefault(const char* name)
{
}
void btLeaveProfileZoneDefault()
{
}
#endif //BT_NO_PROFILE
static btEnterProfileZoneFunc* bts_enterFunc = btEnterProfileZoneDefault;
static btLeaveProfileZoneFunc* bts_leaveFunc = btLeaveProfileZoneDefault;
void btEnterProfileZone(const char* name)
{
(bts_enterFunc)(name);
}
void btLeaveProfileZone()
{
(bts_leaveFunc)();
}
btEnterProfileZoneFunc* btGetCurrentEnterProfileZoneFunc()
{
return bts_enterFunc ;
}
btLeaveProfileZoneFunc* btGetCurrentLeaveProfileZoneFunc()
{
return bts_leaveFunc;
}
void btSetCustomEnterProfileZoneFunc(btEnterProfileZoneFunc* enterFunc)
{
bts_enterFunc = enterFunc;
}
void btSetCustomLeaveProfileZoneFunc(btLeaveProfileZoneFunc* leaveFunc)
{
bts_leaveFunc = leaveFunc;
}
CProfileSample::CProfileSample( const char * name )
{
btEnterProfileZone(name);
}
CProfileSample::~CProfileSample( void )
{
btLeaveProfileZone();
}