Blender V2.61 - r43446
|
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(¤tTime); 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(¤tTime, 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(¤tTime); 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(¤tTime, 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