src/LinearMath/btQuickprof.cpp

   1 /*
   2
   3 ***************************************************************************************************
   4 **
   5 ** profile.cpp
   6 **
   7 ** Real-Time Hierarchical Profiling for Game Programming Gems 3
   8 **
   9 ** by Greg Hjelstrom & Byon Garrabrant
  10 **
  11 ***************************************************************************************************/
  12
  13 // Credits: The Clock class was inspired by the Timer classes in
  14 // Ogre (www.ogre3d.org).
  15
  16 #include "btQuickprof.h"
  17
  18 #ifndef BT_NO_PROFILE
  19
  20
  21 static btClock gProfileClock;
  22
  23
  24 #ifdef __CELLOS_LV2__
  25 #include <sys/sys_time.h>
  26 #include <sys/time_util.h>
  27 #include <stdio.h>
  28 #endif
  29
  30 #if defined (SUNOS) || defined (__SUNOS__)
  31 #include <stdio.h>
  32 #endif
  33
  34 #if defined(WIN32) || defined(_WIN32)
  35
  36 #define BT_USE_WINDOWS_TIMERS
  37 #define WIN32_LEAN_AND_MEAN
  38 #define NOWINRES
  39 #define NOMCX
  40 #define NOIME
  41
  42 #ifdef _XBOX
  43         #include <Xtl.h>
  44 #else //_XBOX
  45         #include <windows.h>
  46 #endif //_XBOX
  47
  48 #include <time.h>
  49
  50
  51 #else //_WIN32
  52 #include <sys/time.h>
  53 #endif //_WIN32
  54
  55 #define mymin(a,b) (a > b ? a : b)
  56
  57 struct btClockData
  58 {
  59
  60 #ifdef BT_USE_WINDOWS_TIMERS
  61         LARGE_INTEGER mClockFrequency;
  62         DWORD mStartTick;
  63         LONGLONG mPrevElapsedTime;
  64         LARGE_INTEGER mStartTime;
  65 #else
  66 #ifdef __CELLOS_LV2__
  67         uint64_t        mStartTime;
  68 #else
  69         struct timeval mStartTime;
  70 #endif
  71 #endif //__CELLOS_LV2__
  72
  73 };
  74
  75 ///The btClock is a portable basic clock that measures accurate time in seconds, use for profiling.
  76 btClock::btClock()
  77 {
  78         m_data = new btClockData;
  79 #ifdef BT_USE_WINDOWS_TIMERS
  80         QueryPerformanceFrequency(&m_data->mClockFrequency);
  81 #endif
  82         reset();
  83 }
  84
  85 btClock::~btClock()
  86 {
  87         delete m_data;
  88 }
  89
  90 btClock::btClock(const btClock& other)
  91 {
  92         m_data = new btClockData;
  93         *m_data = *other.m_data;
  94 }
  95
  96 btClock& btClock::operator=(const btClock& other)
  97 {
  98         *m_data = *other.m_data;
  99         return *this;
 100 }
 101
 102
 103         /// Resets the initial reference time.
 104 void btClock::reset()
 105 {
 106 #ifdef BT_USE_WINDOWS_TIMERS
 107         QueryPerformanceCounter(&m_data->mStartTime);
 108         m_data->mStartTick = GetTickCount();
 109         m_data->mPrevElapsedTime = 0;
 110 #else
 111 #ifdef __CELLOS_LV2__
 112
 113         typedef uint64_t  ClockSize;
 114         ClockSize newTime;
 115         //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 116         SYS_TIMEBASE_GET( newTime );
 117         m_data->mStartTime = newTime;
 118 #else
 119         gettimeofday(&m_data->mStartTime, 0);
 120 #endif
 121 #endif
 122 }
 123
 124 /// Returns the time in ms since the last call to reset or since
 125 /// the btClock was created.
 126 unsigned long int btClock::getTimeMilliseconds()
 127 {
 128 #ifdef BT_USE_WINDOWS_TIMERS
 129         LARGE_INTEGER currentTime;
 130         QueryPerformanceCounter(&currentTime);
 131         LONGLONG elapsedTime = currentTime.QuadPart -
 132                 m_data->mStartTime.QuadPart;
 133                 // Compute the number of millisecond ticks elapsed.
 134         unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
 135                 m_data->mClockFrequency.QuadPart);
 136                 // Check for unexpected leaps in the Win32 performance counter.
 137         // (This is caused by unexpected data across the PCI to ISA
 138                 // bridge, aka south bridge.  See Microsoft KB274323.)
 139                 unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
 140                 signed long msecOff = (signed long)(msecTicks - elapsedTicks);
 141                 if (msecOff < -100 || msecOff > 100)
 142                 {
 143                         // Adjust the starting time forwards.
 144                         LONGLONG msecAdjustment = mymin(msecOff *
 145                                 m_data->mClockFrequency.QuadPart / 1000, elapsedTime -
 146                                 m_data->mPrevElapsedTime);
 147                         m_data->mStartTime.QuadPart += msecAdjustment;
 148                         elapsedTime -= msecAdjustment;
 149
 150                         // Recompute the number of millisecond ticks elapsed.
 151                         msecTicks = (unsigned long)(1000 * elapsedTime /
 152                                 m_data->mClockFrequency.QuadPart);
 153                 }
 154
 155                 // Store the current elapsed time for adjustments next time.
 156                 m_data->mPrevElapsedTime = elapsedTime;
 157
 158                 return msecTicks;
 159 #else
 160
 161 #ifdef __CELLOS_LV2__
 162                 uint64_t freq=sys_time_get_timebase_frequency();
 163                 double dFreq=((double) freq) / 1000.0;
 164                 typedef uint64_t  ClockSize;
 165                 ClockSize newTime;
 166                 SYS_TIMEBASE_GET( newTime );
 167                 //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 168
 169                 return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
 170 #else
 171
 172                 struct timeval currentTime;
 173                 gettimeofday(&currentTime, 0);
 174                 return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000 +
 175                         (currentTime.tv_usec - m_data->mStartTime.tv_usec) / 1000;
 176 #endif //__CELLOS_LV2__
 177 #endif
 178 }
 179
 180         /// Returns the time in us since the last call to reset or since
 181         /// the Clock was created.
 182 unsigned long int btClock::getTimeMicroseconds()
 183 {
 184 #ifdef BT_USE_WINDOWS_TIMERS
 185                 LARGE_INTEGER currentTime;
 186                 QueryPerformanceCounter(&currentTime);
 187                 LONGLONG elapsedTime = currentTime.QuadPart -
 188                         m_data->mStartTime.QuadPart;
 189
 190                 // Compute the number of millisecond ticks elapsed.
 191                 unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
 192                         m_data->mClockFrequency.QuadPart);
 193
 194                 // Check for unexpected leaps in the Win32 performance counter.
 195                 // (This is caused by unexpected data across the PCI to ISA
 196                 // bridge, aka south bridge.  See Microsoft KB274323.)
 197                 unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
 198                 signed long msecOff = (signed long)(msecTicks - elapsedTicks);
 199                 if (msecOff < -100 || msecOff > 100)
 200                 {
 201                         // Adjust the starting time forwards.
 202                         LONGLONG msecAdjustment = mymin(msecOff *
 203                                 m_data->mClockFrequency.QuadPart / 1000, elapsedTime -
 204                                 m_data->mPrevElapsedTime);
 205                         m_data->mStartTime.QuadPart += msecAdjustment;
 206                         elapsedTime -= msecAdjustment;
 207                 }
 208
 209                 // Store the current elapsed time for adjustments next time.
 210                 m_data->mPrevElapsedTime = elapsedTime;
 211
 212                 // Convert to microseconds.
 213                 unsigned long usecTicks = (unsigned long)(1000000 * elapsedTime /
 214                         m_data->mClockFrequency.QuadPart);
 215
 216                 return usecTicks;
 217 #else
 218
 219 #ifdef __CELLOS_LV2__
 220                 uint64_t freq=sys_time_get_timebase_frequency();
 221                 double dFreq=((double) freq)/ 1000000.0;
 222                 typedef uint64_t  ClockSize;
 223                 ClockSize newTime;
 224                 //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 225                 SYS_TIMEBASE_GET( newTime );
 226
 227                 return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
 228 #else
 229
 230                 struct timeval currentTime;
 231                 gettimeofday(&currentTime, 0);
 232                 return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000000 +
 233                         (currentTime.tv_usec - m_data->mStartTime.tv_usec);
 234 #endif//__CELLOS_LV2__
 235 #endif
 236 }
 237
 238
 239
 240
 241
 242 inline void Profile_Get_Ticks(unsigned long int * ticks)
 243 {
 244         *ticks = gProfileClock.getTimeMicroseconds();
 245 }
 246
 247 inline float Profile_Get_Tick_Rate(void)
 248 {
 249 //      return 1000000.f;
 250         return 1000.f;
 251
 252 }
 253
 254
 255
 256 /***************************************************************************************************
 257 **
 258 ** CProfileNode
 259 **
 260 ***************************************************************************************************/
 261
 262 /***********************************************************************************************
 263  * INPUT:                                                                                      *
 264  * name - pointer to a static string which is the name of this profile node                    *
 265  * parent - parent pointer                                                                     *
 266  *                                                                                             *
 267  * WARNINGS:                                                                                   *
 268  * The name is assumed to be a static pointer, only the pointer is stored and compared for     *
 269  * efficiency reasons.                                                                         *
 270  *=============================================================================================*/
 271 CProfileNode::CProfileNode( const char * name, CProfileNode * parent ) :
 272         Name( name ),
 273         TotalCalls( 0 ),
 274         TotalTime( 0 ),
 275         StartTime( 0 ),
 276         RecursionCounter( 0 ),
 277         Parent( parent ),
 278         Child( NULL ),
 279         Sibling( NULL ),
 280         m_userPtr(0)
 281 {
 282         Reset();
 283 }
 284
 285
 286 void    CProfileNode::CleanupMemory()
 287 {
 288         delete ( Child);
 289         Child = NULL;
 290         delete ( Sibling);
 291         Sibling = NULL;
 292 }
 293
 294 CProfileNode::~CProfileNode( void )
 295 {
 296         delete ( Child);
 297         delete ( Sibling);
 298 }
 299
 300
 301 /***********************************************************************************************
 302  * INPUT:                                                                                      *
 303  * name - static string pointer to the name of the node we are searching for                   *
 304  *                                                                                             *
 305  * WARNINGS:                                                                                   *
 306  * All profile names are assumed to be static strings so this function uses pointer compares   *
 307  * to find the named node.                                                                     *
 308  *=============================================================================================*/
 309 CProfileNode * CProfileNode::Get_Sub_Node( const char * name )
 310 {
 311         // Try to find this sub node
 312         CProfileNode * child = Child;
 313         while ( child ) {
 314                 if ( child->Name == name ) {
 315                         return child;
 316                 }
 317                 child = child->Sibling;
 318         }
 319
 320         // We didn't find it, so add it
 321
 322         CProfileNode * node = new CProfileNode( name, this );
 323         node->Sibling = Child;
 324         Child = node;
 325         return node;
 326 }
 327
 328
 329 void    CProfileNode::Reset( void )
 330 {
 331         TotalCalls = 0;
 332         TotalTime = 0.0f;
 333
 334
 335         if ( Child ) {
 336                 Child->Reset();
 337         }
 338         if ( Sibling ) {
 339                 Sibling->Reset();
 340         }
 341 }
 342
 343
 344 void    CProfileNode::Call( void )
 345 {
 346         TotalCalls++;
 347         if (RecursionCounter++ == 0) {
 348                 Profile_Get_Ticks(&StartTime);
 349         }
 350 }
 351
 352
 353 bool    CProfileNode::Return( void )
 354 {
 355         if ( --RecursionCounter == 0 && TotalCalls != 0 ) {
 356                 unsigned long int time;
 357                 Profile_Get_Ticks(&time);
 358                 time-=StartTime;
 359                 TotalTime += (float)time / Profile_Get_Tick_Rate();
 360         }
 361         return ( RecursionCounter == 0 );
 362 }
 363
 364
 365 /***************************************************************************************************
 366 **
 367 ** CProfileIterator
 368 **
 369 ***************************************************************************************************/
 370 CProfileIterator::CProfileIterator( CProfileNode * start )
 371 {
 372         CurrentParent = start;
 373         CurrentChild = CurrentParent->Get_Child();
 374 }
 375
 376
 377 void    CProfileIterator::First(void)
 378 {
 379         CurrentChild = CurrentParent->Get_Child();
 380 }
 381
 382
 383 void    CProfileIterator::Next(void)
 384 {
 385         CurrentChild = CurrentChild->Get_Sibling();
 386 }
 387
 388
 389 bool    CProfileIterator::Is_Done(void)
 390 {
 391         return CurrentChild == NULL;
 392 }
 393
 394
 395 void    CProfileIterator::Enter_Child( int index )
 396 {
 397         CurrentChild = CurrentParent->Get_Child();
 398         while ( (CurrentChild != NULL) && (index != 0) ) {
 399                 index--;
 400                 CurrentChild = CurrentChild->Get_Sibling();
 401         }
 402
 403         if ( CurrentChild != NULL ) {
 404                 CurrentParent = CurrentChild;
 405                 CurrentChild = CurrentParent->Get_Child();
 406         }
 407 }
 408
 409
 410 void    CProfileIterator::Enter_Parent( void )
 411 {
 412         if ( CurrentParent->Get_Parent() != NULL ) {
 413                 CurrentParent = CurrentParent->Get_Parent();
 414         }
 415         CurrentChild = CurrentParent->Get_Child();
 416 }
 417
 418
 419 /***************************************************************************************************
 420 **
 421 ** CProfileManager
 422 **
 423 ***************************************************************************************************/
 424
 425 CProfileNode    CProfileManager::Root( "Root", NULL );
 426 CProfileNode *  CProfileManager::CurrentNode = &CProfileManager::Root;
 427 int                             CProfileManager::FrameCounter = 0;
 428 unsigned long int                       CProfileManager::ResetTime = 0;
 429
 430
 431 /***********************************************************************************************
 432  * CProfileManager::Start_Profile -- Begin a named profile                                    *
 433  *                                                                                             *
 434  * Steps one level deeper into the tree, if a child already exists with the specified name     *
 435  * then it accumulates the profiling; otherwise a new child node is added to the profile tree. *
 436  *                                                                                             *
 437  * INPUT:                                                                                      *
 438  * name - name of this profiling record                                                        *
 439  *                                                                                             *
 440  * WARNINGS:                                                                                   *
 441  * The string used is assumed to be a static string; pointer compares are used throughout      *
 442  * the profiling code for efficiency.                                                          *
 443  *=============================================================================================*/
 444 void    CProfileManager::Start_Profile( const char * name )
 445 {
 446         if (name != CurrentNode->Get_Name()) {
 447                 CurrentNode = CurrentNode->Get_Sub_Node( name );
 448         }
 449
 450         CurrentNode->Call();
 451 }
 452
 453
 454 /***********************************************************************************************
 455  * CProfileManager::Stop_Profile -- Stop timing and record the results.                       *
 456  *=============================================================================================*/
 457 void    CProfileManager::Stop_Profile( void )
 458 {
 459         // Return will indicate whether we should back up to our parent (we may
 460         // be profiling a recursive function)
 461         if (CurrentNode->Return()) {
 462                 CurrentNode = CurrentNode->Get_Parent();
 463         }
 464 }
 465
 466
 467 /***********************************************************************************************
 468  * CProfileManager::Reset -- Reset the contents of the profiling system                       *
 469  *                                                                                             *
 470  *    This resets everything except for the tree structure.  All of the timing data is reset.  *
 471  *=============================================================================================*/
 472 void    CProfileManager::Reset( void )
 473 {
 474         gProfileClock.reset();
 475         Root.Reset();
 476     Root.Call();
 477         FrameCounter = 0;
 478         Profile_Get_Ticks(&ResetTime);
 479 }
 480
 481
 482 /***********************************************************************************************
 483  * CProfileManager::Increment_Frame_Counter -- Increment the frame counter                    *
 484  *=============================================================================================*/
 485 void CProfileManager::Increment_Frame_Counter( void )
 486 {
 487         FrameCounter++;
 488 }
 489
 490
 491 /***********************************************************************************************
 492  * CProfileManager::Get_Time_Since_Reset -- returns the elapsed time since last reset         *
 493  *=============================================================================================*/
 494 float CProfileManager::Get_Time_Since_Reset( void )
 495 {
 496         unsigned long int time;
 497         Profile_Get_Ticks(&time);
 498         time -= ResetTime;
 499         return (float)time / Profile_Get_Tick_Rate();
 500 }
 501
 502 #include <stdio.h>
 503
 504 void    CProfileManager::dumpRecursive(CProfileIterator* profileIterator, int spacing)
 505 {
 506         profileIterator->First();
 507         if (profileIterator->Is_Done())
 508                 return;
 509
 510         float accumulated_time=0,parent_time = profileIterator->Is_Root() ? CProfileManager::Get_Time_Since_Reset() : profileIterator->Get_Current_Parent_Total_Time();
 511         int i;
 512         int frames_since_reset = CProfileManager::Get_Frame_Count_Since_Reset();
 513         for (i=0;i<spacing;i++) printf(".");
 514         printf("----------------------------------\n");
 515         for (i=0;i<spacing;i++) printf(".");
 516         printf("Profiling: %s (total running time: %.3f ms) ---\n",     profileIterator->Get_Current_Parent_Name(), parent_time );
 517         float totalTime = 0.f;
 518
 519
 520         int numChildren = 0;
 521
 522         for (i = 0; !profileIterator->Is_Done(); i++,profileIterator->Next())
 523         {
 524                 numChildren++;
 525                 float current_total_time = profileIterator->Get_Current_Total_Time();
 526                 accumulated_time += current_total_time;
 527                 float fraction = parent_time > SIMD_EPSILON ? (current_total_time / parent_time) * 100 : 0.f;
 528                 {
 529                         int i;  for (i=0;i<spacing;i++) printf(".");
 530                 }
 531                 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());
 532                 totalTime += current_total_time;
 533                 //recurse into children
 534         }
 535
 536         if (parent_time < accumulated_time)
 537         {
 538                 printf("what's wrong\n");
 539         }
 540         for (i=0;i<spacing;i++) printf(".");
 541         printf("%s (%.3f %%) :: %.3f ms\n", "Unaccounted:",parent_time > SIMD_EPSILON ? ((parent_time - accumulated_time) / parent_time) * 100 : 0.f, parent_time - accumulated_time);
 542
 543         for (i=0;i<numChildren;i++)
 544         {
 545                 profileIterator->Enter_Child(i);
 546                 dumpRecursive(profileIterator,spacing+3);
 547                 profileIterator->Enter_Parent();
 548         }
 549 }
 550
 551
 552
 553 void    CProfileManager::dumpAll()
 554 {
 555         CProfileIterator* profileIterator = 0;
 556         profileIterator = CProfileManager::Get_Iterator();
 557
 558         dumpRecursive(profileIterator,0);
 559
 560         CProfileManager::Release_Iterator(profileIterator);
 561 }
 562
 563
 564
 565
 566 #endif //BT_NO_PROFILE