Blender V2.61 - r43446

btQuickprof.cpp

Go to the documentation of this file.
00001 /*
00002 
00003 ***************************************************************************************************
00004 **
00005 ** profile.cpp
00006 **
00007 ** Real-Time Hierarchical Profiling for Game Programming Gems 3
00008 **
00009 ** by Greg Hjelstrom & Byon Garrabrant
00010 **
00011 ***************************************************************************************************/
00012 
00013 // Credits: The Clock class was inspired by the Timer classes in 
00014 // Ogre (www.ogre3d.org).
00015 
00016 #include "btQuickprof.h"
00017 
00018 #ifndef BT_NO_PROFILE
00019 
00020 
00021 static btClock gProfileClock;
00022 
00023 
00024 #ifdef __CELLOS_LV2__
00025 #include <sys/sys_time.h>
00026 #include <sys/time_util.h>
00027 #include <stdio.h>
00028 #endif
00029 
00030 #if defined (SUNOS) || defined (__SUNOS__) 
00031 #include <stdio.h> 
00032 #endif
00033 
00034 #if defined(WIN32) || defined(_WIN32)
00035 
00036 #define BT_USE_WINDOWS_TIMERS
00037 #define WIN32_LEAN_AND_MEAN
00038 #define NOWINRES
00039 #define NOMCX
00040 #define NOIME 
00041 
00042 #ifdef _XBOX
00043     #include <Xtl.h>
00044 #else //_XBOX
00045     #include <windows.h>
00046 #endif //_XBOX
00047 
00048 #include <time.h>
00049 
00050 
00051 #else //_WIN32
00052 #include <sys/time.h>
00053 #endif //_WIN32
00054 
00055 #define mymin(a,b) (a > b ? a : b)
00056 
00057 struct btClockData
00058 {
00059 
00060 #ifdef BT_USE_WINDOWS_TIMERS
00061     LARGE_INTEGER mClockFrequency;
00062     DWORD mStartTick;
00063     LONGLONG mPrevElapsedTime;
00064     LARGE_INTEGER mStartTime;
00065 #else
00066 #ifdef __CELLOS_LV2__
00067     uint64_t    mStartTime;
00068 #else
00069     struct timeval mStartTime;
00070 #endif
00071 #endif //__CELLOS_LV2__
00072 
00073 };
00074 
00076 btClock::btClock()
00077 {
00078     m_data = new btClockData;
00079 #ifdef BT_USE_WINDOWS_TIMERS
00080     QueryPerformanceFrequency(&m_data->mClockFrequency);
00081 #endif
00082     reset();
00083 }
00084 
00085 btClock::~btClock()
00086 {
00087     delete m_data;
00088 }
00089 
00090 btClock::btClock(const btClock& other)
00091 {
00092     m_data = new btClockData;
00093     *m_data = *other.m_data;
00094 }
00095 
00096 btClock& btClock::operator=(const btClock& other)
00097 {
00098     *m_data = *other.m_data;
00099     return *this;
00100 }
00101 
00102 
00104 void btClock::reset()
00105 {
00106 #ifdef BT_USE_WINDOWS_TIMERS
00107     QueryPerformanceCounter(&m_data->mStartTime);
00108     m_data->mStartTick = GetTickCount();
00109     m_data->mPrevElapsedTime = 0;
00110 #else
00111 #ifdef __CELLOS_LV2__
00112 
00113     typedef uint64_t  ClockSize;
00114     ClockSize newTime;
00115     //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
00116     SYS_TIMEBASE_GET( newTime );
00117     m_data->mStartTime = newTime;
00118 #else
00119     gettimeofday(&m_data->mStartTime, 0);
00120 #endif
00121 #endif
00122 }
00123 
00126 unsigned long int btClock::getTimeMilliseconds()
00127 {
00128 #ifdef BT_USE_WINDOWS_TIMERS
00129     LARGE_INTEGER currentTime;
00130     QueryPerformanceCounter(&currentTime);
00131     LONGLONG elapsedTime = currentTime.QuadPart - 
00132         m_data->mStartTime.QuadPart;
00133         // Compute the number of millisecond ticks elapsed.
00134     unsigned long msecTicks = (unsigned long)(1000 * elapsedTime / 
00135         m_data->mClockFrequency.QuadPart);
00136         // Check for unexpected leaps in the Win32 performance counter.  
00137     // (This is caused by unexpected data across the PCI to ISA 
00138         // bridge, aka south bridge.  See Microsoft KB274323.)
00139         unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
00140         signed long msecOff = (signed long)(msecTicks - elapsedTicks);
00141         if (msecOff < -100 || msecOff > 100)
00142         {
00143             // Adjust the starting time forwards.
00144             LONGLONG msecAdjustment = mymin(msecOff * 
00145                 m_data->mClockFrequency.QuadPart / 1000, elapsedTime - 
00146                 m_data->mPrevElapsedTime);
00147             m_data->mStartTime.QuadPart += msecAdjustment;
00148             elapsedTime -= msecAdjustment;
00149 
00150             // Recompute the number of millisecond ticks elapsed.
00151             msecTicks = (unsigned long)(1000 * elapsedTime / 
00152                 m_data->mClockFrequency.QuadPart);
00153         }
00154 
00155         // Store the current elapsed time for adjustments next time.
00156         m_data->mPrevElapsedTime = elapsedTime;
00157 
00158         return msecTicks;
00159 #else
00160 
00161 #ifdef __CELLOS_LV2__
00162         uint64_t freq=sys_time_get_timebase_frequency();
00163         double dFreq=((double) freq) / 1000.0;
00164         typedef uint64_t  ClockSize;
00165         ClockSize newTime;
00166         SYS_TIMEBASE_GET( newTime );
00167         //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
00168 
00169         return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
00170 #else
00171 
00172         struct timeval currentTime;
00173         gettimeofday(&currentTime, 0);
00174         return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000 + 
00175             (currentTime.tv_usec - m_data->mStartTime.tv_usec) / 1000;
00176 #endif //__CELLOS_LV2__
00177 #endif
00178 }
00179 
00182 unsigned long int btClock::getTimeMicroseconds()
00183 {
00184 #ifdef BT_USE_WINDOWS_TIMERS
00185         LARGE_INTEGER currentTime;
00186         QueryPerformanceCounter(&currentTime);
00187         LONGLONG elapsedTime = currentTime.QuadPart - 
00188             m_data->mStartTime.QuadPart;
00189 
00190         // Compute the number of millisecond ticks elapsed.
00191         unsigned long msecTicks = (unsigned long)(1000 * elapsedTime / 
00192             m_data->mClockFrequency.QuadPart);
00193 
00194         // Check for unexpected leaps in the Win32 performance counter.  
00195         // (This is caused by unexpected data across the PCI to ISA 
00196         // bridge, aka south bridge.  See Microsoft KB274323.)
00197         unsigned long elapsedTicks = GetTickCount() - m_data->mStartTick;
00198         signed long msecOff = (signed long)(msecTicks - elapsedTicks);
00199         if (msecOff < -100 || msecOff > 100)
00200         {
00201             // Adjust the starting time forwards.
00202             LONGLONG msecAdjustment = mymin(msecOff * 
00203                 m_data->mClockFrequency.QuadPart / 1000, elapsedTime - 
00204                 m_data->mPrevElapsedTime);
00205             m_data->mStartTime.QuadPart += msecAdjustment;
00206             elapsedTime -= msecAdjustment;
00207         }
00208 
00209         // Store the current elapsed time for adjustments next time.
00210         m_data->mPrevElapsedTime = elapsedTime;
00211 
00212         // Convert to microseconds.
00213         unsigned long usecTicks = (unsigned long)(1000000 * elapsedTime / 
00214             m_data->mClockFrequency.QuadPart);
00215 
00216         return usecTicks;
00217 #else
00218 
00219 #ifdef __CELLOS_LV2__
00220         uint64_t freq=sys_time_get_timebase_frequency();
00221         double dFreq=((double) freq)/ 1000000.0;
00222         typedef uint64_t  ClockSize;
00223         ClockSize newTime;
00224         //__asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
00225         SYS_TIMEBASE_GET( newTime );
00226 
00227         return (unsigned long int)((double(newTime-m_data->mStartTime)) / dFreq);
00228 #else
00229 
00230         struct timeval currentTime;
00231         gettimeofday(&currentTime, 0);
00232         return (currentTime.tv_sec - m_data->mStartTime.tv_sec) * 1000000 + 
00233             (currentTime.tv_usec - m_data->mStartTime.tv_usec);
00234 #endif//__CELLOS_LV2__
00235 #endif 
00236 }
00237 
00238 
00239 
00240 
00241 
00242 inline void Profile_Get_Ticks(unsigned long int * ticks)
00243 {
00244     *ticks = gProfileClock.getTimeMicroseconds();
00245 }
00246 
00247 inline float Profile_Get_Tick_Rate(void)
00248 {
00249 //  return 1000000.f;
00250     return 1000.f;
00251 
00252 }
00253 
00254 
00255 
00256 /***************************************************************************************************
00257 **
00258 ** CProfileNode
00259 **
00260 ***************************************************************************************************/
00261 
00262 /***********************************************************************************************
00263  * INPUT:                                                                                      *
00264  * name - pointer to a static string which is the name of this profile node                    *
00265  * parent - parent pointer                                                                     *
00266  *                                                                                             *
00267  * WARNINGS:                                                                                   *
00268  * The name is assumed to be a static pointer, only the pointer is stored and compared for     *
00269  * efficiency reasons.                                                                         *
00270  *=============================================================================================*/
00271 CProfileNode::CProfileNode( const char * name, CProfileNode * parent ) :
00272     Name( name ),
00273     TotalCalls( 0 ),
00274     TotalTime( 0 ),
00275     StartTime( 0 ),
00276     RecursionCounter( 0 ),
00277     Parent( parent ),
00278     Child( NULL ),
00279     Sibling( NULL )
00280 {
00281     Reset();
00282 }
00283 
00284 
00285 void    CProfileNode::CleanupMemory()
00286 {
00287     delete ( Child);
00288     Child = NULL;
00289     delete ( Sibling);
00290     Sibling = NULL;
00291 }
00292 
00293 CProfileNode::~CProfileNode( void )
00294 {
00295     delete ( Child);
00296     delete ( Sibling);
00297 }
00298 
00299 
00300 /***********************************************************************************************
00301  * INPUT:                                                                                      *
00302  * name - static string pointer to the name of the node we are searching for                   *
00303  *                                                                                             *
00304  * WARNINGS:                                                                                   *
00305  * All profile names are assumed to be static strings so this function uses pointer compares   *
00306  * to find the named node.                                                                     *
00307  *=============================================================================================*/
00308 CProfileNode * CProfileNode::Get_Sub_Node( const char * name )
00309 {
00310     // Try to find this sub node
00311     CProfileNode * child = Child;
00312     while ( child ) {
00313         if ( child->Name == name ) {
00314             return child;
00315         }
00316         child = child->Sibling;
00317     }
00318 
00319     // We didn't find it, so add it
00320     
00321     CProfileNode * node = new CProfileNode( name, this );
00322     node->Sibling = Child;
00323     Child = node;
00324     return node;
00325 }
00326 
00327 
00328 void    CProfileNode::Reset( void )
00329 {
00330     TotalCalls = 0;
00331     TotalTime = 0.0f;
00332     
00333 
00334     if ( Child ) {
00335         Child->Reset();
00336     }
00337     if ( Sibling ) {
00338         Sibling->Reset();
00339     }
00340 }
00341 
00342 
00343 void    CProfileNode::Call( void )
00344 {
00345     TotalCalls++;
00346     if (RecursionCounter++ == 0) {
00347         Profile_Get_Ticks(&StartTime);
00348     }
00349 }
00350 
00351 
00352 bool    CProfileNode::Return( void )
00353 {
00354     if ( --RecursionCounter == 0 && TotalCalls != 0 ) { 
00355         unsigned long int time;
00356         Profile_Get_Ticks(&time);
00357         time-=StartTime;
00358         TotalTime += (float)time / Profile_Get_Tick_Rate();
00359     }
00360     return ( RecursionCounter == 0 );
00361 }
00362 
00363 
00364 /***************************************************************************************************
00365 **
00366 ** CProfileIterator
00367 **
00368 ***************************************************************************************************/
00369 CProfileIterator::CProfileIterator( CProfileNode * start )
00370 {
00371     CurrentParent = start;
00372     CurrentChild = CurrentParent->Get_Child();
00373 }
00374 
00375 
00376 void    CProfileIterator::First(void)
00377 {
00378     CurrentChild = CurrentParent->Get_Child();
00379 }
00380 
00381 
00382 void    CProfileIterator::Next(void)
00383 {
00384     CurrentChild = CurrentChild->Get_Sibling();
00385 }
00386 
00387 
00388 bool    CProfileIterator::Is_Done(void)
00389 {
00390     return CurrentChild == NULL;
00391 }
00392 
00393 
00394 void    CProfileIterator::Enter_Child( int index )
00395 {
00396     CurrentChild = CurrentParent->Get_Child();
00397     while ( (CurrentChild != NULL) && (index != 0) ) {
00398         index--;
00399         CurrentChild = CurrentChild->Get_Sibling();
00400     }
00401 
00402     if ( CurrentChild != NULL ) {
00403         CurrentParent = CurrentChild;
00404         CurrentChild = CurrentParent->Get_Child();
00405     }
00406 }
00407 
00408 
00409 void    CProfileIterator::Enter_Parent( void )
00410 {
00411     if ( CurrentParent->Get_Parent() != NULL ) {
00412         CurrentParent = CurrentParent->Get_Parent();
00413     }
00414     CurrentChild = CurrentParent->Get_Child();
00415 }
00416 
00417 
00418 /***************************************************************************************************
00419 **
00420 ** CProfileManager
00421 **
00422 ***************************************************************************************************/
00423 
00424 CProfileNode    CProfileManager::Root( "Root", NULL );
00425 CProfileNode *  CProfileManager::CurrentNode = &CProfileManager::Root;
00426 int             CProfileManager::FrameCounter = 0;
00427 unsigned long int           CProfileManager::ResetTime = 0;
00428 
00429 
00430 /***********************************************************************************************
00431  * CProfileManager::Start_Profile -- Begin a named profile                                    *
00432  *                                                                                             *
00433  * Steps one level deeper into the tree, if a child already exists with the specified name     *
00434  * then it accumulates the profiling; otherwise a new child node is added to the profile tree. *
00435  *                                                                                             *
00436  * INPUT:                                                                                      *
00437  * name - name of this profiling record                                                        *
00438  *                                                                                             *
00439  * WARNINGS:                                                                                   *
00440  * The string used is assumed to be a static string; pointer compares are used throughout      *
00441  * the profiling code for efficiency.                                                          *
00442  *=============================================================================================*/
00443 void    CProfileManager::Start_Profile( const char * name )
00444 {
00445     if (name != CurrentNode->Get_Name()) {
00446         CurrentNode = CurrentNode->Get_Sub_Node( name );
00447     } 
00448     
00449     CurrentNode->Call();
00450 }
00451 
00452 
00453 /***********************************************************************************************
00454  * CProfileManager::Stop_Profile -- Stop timing and record the results.                       *
00455  *=============================================================================================*/
00456 void    CProfileManager::Stop_Profile( void )
00457 {
00458     // Return will indicate whether we should back up to our parent (we may
00459     // be profiling a recursive function)
00460     if (CurrentNode->Return()) {
00461         CurrentNode = CurrentNode->Get_Parent();
00462     }
00463 }
00464 
00465 
00466 /***********************************************************************************************
00467  * CProfileManager::Reset -- Reset the contents of the profiling system                       *
00468  *                                                                                             *
00469  *    This resets everything except for the tree structure.  All of the timing data is reset.  *
00470  *=============================================================================================*/
00471 void    CProfileManager::Reset( void )
00472 { 
00473     gProfileClock.reset();
00474     Root.Reset();
00475     Root.Call();
00476     FrameCounter = 0;
00477     Profile_Get_Ticks(&ResetTime);
00478 }
00479 
00480 
00481 /***********************************************************************************************
00482  * CProfileManager::Increment_Frame_Counter -- Increment the frame counter                    *
00483  *=============================================================================================*/
00484 void CProfileManager::Increment_Frame_Counter( void )
00485 {
00486     FrameCounter++;
00487 }
00488 
00489 
00490 /***********************************************************************************************
00491  * CProfileManager::Get_Time_Since_Reset -- returns the elapsed time since last reset         *
00492  *=============================================================================================*/
00493 float CProfileManager::Get_Time_Since_Reset( void )
00494 {
00495     unsigned long int time;
00496     Profile_Get_Ticks(&time);
00497     time -= ResetTime;
00498     return (float)time / Profile_Get_Tick_Rate();
00499 }
00500 
00501 #include <stdio.h>
00502 
00503 void    CProfileManager::dumpRecursive(CProfileIterator* profileIterator, int spacing)
00504 {
00505     profileIterator->First();
00506     if (profileIterator->Is_Done())
00507         return;
00508 
00509     float accumulated_time=0,parent_time = profileIterator->Is_Root() ? CProfileManager::Get_Time_Since_Reset() : profileIterator->Get_Current_Parent_Total_Time();
00510     int i;
00511     int frames_since_reset = CProfileManager::Get_Frame_Count_Since_Reset();
00512     for (i=0;i<spacing;i++) printf(".");
00513     printf("----------------------------------\n");
00514     for (i=0;i<spacing;i++) printf(".");
00515     printf("Profiling: %s (total running time: %.3f ms) ---\n", profileIterator->Get_Current_Parent_Name(), parent_time );
00516     float totalTime = 0.f;
00517 
00518     
00519     int numChildren = 0;
00520     
00521     for (i = 0; !profileIterator->Is_Done(); i++,profileIterator->Next())
00522     {
00523         numChildren++;
00524         float current_total_time = profileIterator->Get_Current_Total_Time();
00525         accumulated_time += current_total_time;
00526         float fraction = parent_time > SIMD_EPSILON ? (current_total_time / parent_time) * 100 : 0.f;
00527         {
00528             int i;  for (i=0;i<spacing;i++) printf(".");
00529         }
00530         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());
00531         totalTime += current_total_time;
00532         //recurse into children
00533     }
00534 
00535     if (parent_time < accumulated_time)
00536     {
00537         printf("what's wrong\n");
00538     }
00539     for (i=0;i<spacing;i++) printf(".");
00540     printf("%s (%.3f %%) :: %.3f ms\n", "Unaccounted:",parent_time > SIMD_EPSILON ? ((parent_time - accumulated_time) / parent_time) * 100 : 0.f, parent_time - accumulated_time);
00541     
00542     for (i=0;i<numChildren;i++)
00543     {
00544         profileIterator->Enter_Child(i);
00545         dumpRecursive(profileIterator,spacing+3);
00546         profileIterator->Enter_Parent();
00547     }
00548 }
00549 
00550 
00551 
00552 void    CProfileManager::dumpAll()
00553 {
00554     CProfileIterator* profileIterator = 0;
00555     profileIterator = CProfileManager::Get_Iterator();
00556 
00557     dumpRecursive(profileIterator,0);
00558 
00559     CProfileManager::Release_Iterator(profileIterator);
00560 }
00561 
00562 
00563 
00564 
00565 #endif //BT_NO_PROFILE