bullet: Update to current svn, r2636
[blender.git] / extern / bullet2 / 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