| 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 "LinearMath/btQuickprof.h" | 
|---|
| 17 |  | 
|---|
| 18 |  | 
|---|
| 19 | #ifdef USE_BT_CLOCK | 
|---|
| 20 |  | 
|---|
| 21 | static btClock gProfileClock; | 
|---|
| 22 |  | 
|---|
| 23 | inline void Profile_Get_Ticks(unsigned long int * ticks) | 
|---|
| 24 | { | 
|---|
| 25 | *ticks = gProfileClock.getTimeMicroseconds(); | 
|---|
| 26 | } | 
|---|
| 27 |  | 
|---|
| 28 | inline float Profile_Get_Tick_Rate(void) | 
|---|
| 29 | { | 
|---|
| 30 | //      return 1000000.f; | 
|---|
| 31 | return 1000.f; | 
|---|
| 32 |  | 
|---|
| 33 | } | 
|---|
| 34 |  | 
|---|
| 35 |  | 
|---|
| 36 |  | 
|---|
| 37 | /*************************************************************************************************** | 
|---|
| 38 | ** | 
|---|
| 39 | ** CProfileNode | 
|---|
| 40 | ** | 
|---|
| 41 | ***************************************************************************************************/ | 
|---|
| 42 |  | 
|---|
| 43 | /*********************************************************************************************** | 
|---|
| 44 | * INPUT:                                                                                      * | 
|---|
| 45 | * name - pointer to a static string which is the name of this profile node                    * | 
|---|
| 46 | * parent - parent pointer                                                                     * | 
|---|
| 47 | *                                                                                             * | 
|---|
| 48 | * WARNINGS:                                                                                   * | 
|---|
| 49 | * The name is assumed to be a static pointer, only the pointer is stored and compared for     * | 
|---|
| 50 | * efficiency reasons.                                                                         * | 
|---|
| 51 | *=============================================================================================*/ | 
|---|
| 52 | CProfileNode::CProfileNode( const char * name, CProfileNode * parent ) : | 
|---|
| 53 | Name( name ), | 
|---|
| 54 | TotalCalls( 0 ), | 
|---|
| 55 | TotalTime( 0 ), | 
|---|
| 56 | StartTime( 0 ), | 
|---|
| 57 | RecursionCounter( 0 ), | 
|---|
| 58 | Parent( parent ), | 
|---|
| 59 | Child( NULL ), | 
|---|
| 60 | Sibling( NULL ) | 
|---|
| 61 | { | 
|---|
| 62 | Reset(); | 
|---|
| 63 | } | 
|---|
| 64 |  | 
|---|
| 65 |  | 
|---|
| 66 | void    CProfileNode::CleanupMemory() | 
|---|
| 67 | { | 
|---|
| 68 | delete ( Child); | 
|---|
| 69 | Child = NULL; | 
|---|
| 70 | delete ( Sibling); | 
|---|
| 71 | Sibling = NULL; | 
|---|
| 72 | } | 
|---|
| 73 |  | 
|---|
| 74 | CProfileNode::~CProfileNode( void ) | 
|---|
| 75 | { | 
|---|
| 76 | delete ( Child); | 
|---|
| 77 | delete ( Sibling); | 
|---|
| 78 | } | 
|---|
| 79 |  | 
|---|
| 80 |  | 
|---|
| 81 | /*********************************************************************************************** | 
|---|
| 82 | * INPUT:                                                                                      * | 
|---|
| 83 | * name - static string pointer to the name of the node we are searching for                   * | 
|---|
| 84 | *                                                                                             * | 
|---|
| 85 | * WARNINGS:                                                                                   * | 
|---|
| 86 | * All profile names are assumed to be static strings so this function uses pointer compares   * | 
|---|
| 87 | * to find the named node.                                                                     * | 
|---|
| 88 | *=============================================================================================*/ | 
|---|
| 89 | CProfileNode * CProfileNode::Get_Sub_Node( const char * name ) | 
|---|
| 90 | { | 
|---|
| 91 | // Try to find this sub node | 
|---|
| 92 | CProfileNode * child = Child; | 
|---|
| 93 | while ( child ) { | 
|---|
| 94 | if ( child->Name == name ) { | 
|---|
| 95 | return child; | 
|---|
| 96 | } | 
|---|
| 97 | child = child->Sibling; | 
|---|
| 98 | } | 
|---|
| 99 |  | 
|---|
| 100 | // We didn't find it, so add it | 
|---|
| 101 |  | 
|---|
| 102 | CProfileNode * node = new CProfileNode( name, this ); | 
|---|
| 103 | node->Sibling = Child; | 
|---|
| 104 | Child = node; | 
|---|
| 105 | return node; | 
|---|
| 106 | } | 
|---|
| 107 |  | 
|---|
| 108 |  | 
|---|
| 109 | void    CProfileNode::Reset( void ) | 
|---|
| 110 | { | 
|---|
| 111 | TotalCalls = 0; | 
|---|
| 112 | TotalTime = 0.0f; | 
|---|
| 113 |  | 
|---|
| 114 |  | 
|---|
| 115 | if ( Child ) { | 
|---|
| 116 | Child->Reset(); | 
|---|
| 117 | } | 
|---|
| 118 | if ( Sibling ) { | 
|---|
| 119 | Sibling->Reset(); | 
|---|
| 120 | } | 
|---|
| 121 | } | 
|---|
| 122 |  | 
|---|
| 123 |  | 
|---|
| 124 | void    CProfileNode::Call( void ) | 
|---|
| 125 | { | 
|---|
| 126 | TotalCalls++; | 
|---|
| 127 | if (RecursionCounter++ == 0) { | 
|---|
| 128 | Profile_Get_Ticks(&StartTime); | 
|---|
| 129 | } | 
|---|
| 130 | } | 
|---|
| 131 |  | 
|---|
| 132 |  | 
|---|
| 133 | bool    CProfileNode::Return( void ) | 
|---|
| 134 | { | 
|---|
| 135 | if ( --RecursionCounter == 0 && TotalCalls != 0 ) { | 
|---|
| 136 | unsigned long int time; | 
|---|
| 137 | Profile_Get_Ticks(&time); | 
|---|
| 138 | time-=StartTime; | 
|---|
| 139 | TotalTime += (float)time / Profile_Get_Tick_Rate(); | 
|---|
| 140 | } | 
|---|
| 141 | return ( RecursionCounter == 0 ); | 
|---|
| 142 | } | 
|---|
| 143 |  | 
|---|
| 144 |  | 
|---|
| 145 | /*************************************************************************************************** | 
|---|
| 146 | ** | 
|---|
| 147 | ** CProfileIterator | 
|---|
| 148 | ** | 
|---|
| 149 | ***************************************************************************************************/ | 
|---|
| 150 | CProfileIterator::CProfileIterator( CProfileNode * start ) | 
|---|
| 151 | { | 
|---|
| 152 | CurrentParent = start; | 
|---|
| 153 | CurrentChild = CurrentParent->Get_Child(); | 
|---|
| 154 | } | 
|---|
| 155 |  | 
|---|
| 156 |  | 
|---|
| 157 | void    CProfileIterator::First(void) | 
|---|
| 158 | { | 
|---|
| 159 | CurrentChild = CurrentParent->Get_Child(); | 
|---|
| 160 | } | 
|---|
| 161 |  | 
|---|
| 162 |  | 
|---|
| 163 | void    CProfileIterator::Next(void) | 
|---|
| 164 | { | 
|---|
| 165 | CurrentChild = CurrentChild->Get_Sibling(); | 
|---|
| 166 | } | 
|---|
| 167 |  | 
|---|
| 168 |  | 
|---|
| 169 | bool    CProfileIterator::Is_Done(void) | 
|---|
| 170 | { | 
|---|
| 171 | return CurrentChild == NULL; | 
|---|
| 172 | } | 
|---|
| 173 |  | 
|---|
| 174 |  | 
|---|
| 175 | void    CProfileIterator::Enter_Child( int index ) | 
|---|
| 176 | { | 
|---|
| 177 | CurrentChild = CurrentParent->Get_Child(); | 
|---|
| 178 | while ( (CurrentChild != NULL) && (index != 0) ) { | 
|---|
| 179 | index--; | 
|---|
| 180 | CurrentChild = CurrentChild->Get_Sibling(); | 
|---|
| 181 | } | 
|---|
| 182 |  | 
|---|
| 183 | if ( CurrentChild != NULL ) { | 
|---|
| 184 | CurrentParent = CurrentChild; | 
|---|
| 185 | CurrentChild = CurrentParent->Get_Child(); | 
|---|
| 186 | } | 
|---|
| 187 | } | 
|---|
| 188 |  | 
|---|
| 189 |  | 
|---|
| 190 | void    CProfileIterator::Enter_Parent( void ) | 
|---|
| 191 | { | 
|---|
| 192 | if ( CurrentParent->Get_Parent() != NULL ) { | 
|---|
| 193 | CurrentParent = CurrentParent->Get_Parent(); | 
|---|
| 194 | } | 
|---|
| 195 | CurrentChild = CurrentParent->Get_Child(); | 
|---|
| 196 | } | 
|---|
| 197 |  | 
|---|
| 198 |  | 
|---|
| 199 | /*************************************************************************************************** | 
|---|
| 200 | ** | 
|---|
| 201 | ** CProfileManager | 
|---|
| 202 | ** | 
|---|
| 203 | ***************************************************************************************************/ | 
|---|
| 204 |  | 
|---|
| 205 | CProfileNode    CProfileManager::Root( "Root", NULL ); | 
|---|
| 206 | CProfileNode *  CProfileManager::CurrentNode = &CProfileManager::Root; | 
|---|
| 207 | int                             CProfileManager::FrameCounter = 0; | 
|---|
| 208 | unsigned long int                       CProfileManager::ResetTime = 0; | 
|---|
| 209 |  | 
|---|
| 210 |  | 
|---|
| 211 | /*********************************************************************************************** | 
|---|
| 212 | * CProfileManager::Start_Profile -- Begin a named profile                                    * | 
|---|
| 213 | *                                                                                             * | 
|---|
| 214 | * Steps one level deeper into the tree, if a child already exists with the specified name     * | 
|---|
| 215 | * then it accumulates the profiling; otherwise a new child node is added to the profile tree. * | 
|---|
| 216 | *                                                                                             * | 
|---|
| 217 | * INPUT:                                                                                      * | 
|---|
| 218 | * name - name of this profiling record                                                        * | 
|---|
| 219 | *                                                                                             * | 
|---|
| 220 | * WARNINGS:                                                                                   * | 
|---|
| 221 | * The string used is assumed to be a static string; pointer compares are used throughout      * | 
|---|
| 222 | * the profiling code for efficiency.                                                          * | 
|---|
| 223 | *=============================================================================================*/ | 
|---|
| 224 | void    CProfileManager::Start_Profile( const char * name ) | 
|---|
| 225 | { | 
|---|
| 226 | if (name != CurrentNode->Get_Name()) { | 
|---|
| 227 | CurrentNode = CurrentNode->Get_Sub_Node( name ); | 
|---|
| 228 | } | 
|---|
| 229 |  | 
|---|
| 230 | CurrentNode->Call(); | 
|---|
| 231 | } | 
|---|
| 232 |  | 
|---|
| 233 |  | 
|---|
| 234 | /*********************************************************************************************** | 
|---|
| 235 | * CProfileManager::Stop_Profile -- Stop timing and record the results.                       * | 
|---|
| 236 | *=============================================================================================*/ | 
|---|
| 237 | void    CProfileManager::Stop_Profile( void ) | 
|---|
| 238 | { | 
|---|
| 239 | // Return will indicate whether we should back up to our parent (we may | 
|---|
| 240 | // be profiling a recursive function) | 
|---|
| 241 | if (CurrentNode->Return()) { | 
|---|
| 242 | CurrentNode = CurrentNode->Get_Parent(); | 
|---|
| 243 | } | 
|---|
| 244 | } | 
|---|
| 245 |  | 
|---|
| 246 |  | 
|---|
| 247 | /*********************************************************************************************** | 
|---|
| 248 | * CProfileManager::Reset -- Reset the contents of the profiling system                       * | 
|---|
| 249 | *                                                                                             * | 
|---|
| 250 | *    This resets everything except for the tree structure.  All of the timing data is reset.  * | 
|---|
| 251 | *=============================================================================================*/ | 
|---|
| 252 | void    CProfileManager::Reset( void ) | 
|---|
| 253 | { | 
|---|
| 254 | gProfileClock.reset(); | 
|---|
| 255 | Root.Reset(); | 
|---|
| 256 | Root.Call(); | 
|---|
| 257 | FrameCounter = 0; | 
|---|
| 258 | Profile_Get_Ticks(&ResetTime); | 
|---|
| 259 | } | 
|---|
| 260 |  | 
|---|
| 261 |  | 
|---|
| 262 | /*********************************************************************************************** | 
|---|
| 263 | * CProfileManager::Increment_Frame_Counter -- Increment the frame counter                    * | 
|---|
| 264 | *=============================================================================================*/ | 
|---|
| 265 | void CProfileManager::Increment_Frame_Counter( void ) | 
|---|
| 266 | { | 
|---|
| 267 | FrameCounter++; | 
|---|
| 268 | } | 
|---|
| 269 |  | 
|---|
| 270 |  | 
|---|
| 271 | /*********************************************************************************************** | 
|---|
| 272 | * CProfileManager::Get_Time_Since_Reset -- returns the elapsed time since last reset         * | 
|---|
| 273 | *=============================================================================================*/ | 
|---|
| 274 | float CProfileManager::Get_Time_Since_Reset( void ) | 
|---|
| 275 | { | 
|---|
| 276 | unsigned long int time; | 
|---|
| 277 | Profile_Get_Ticks(&time); | 
|---|
| 278 | time -= ResetTime; | 
|---|
| 279 | return (float)time / Profile_Get_Tick_Rate(); | 
|---|
| 280 | } | 
|---|
| 281 |  | 
|---|
| 282 | #include <stdio.h> | 
|---|
| 283 |  | 
|---|
| 284 | void    CProfileManager::dumpRecursive(CProfileIterator* profileIterator, int spacing) | 
|---|
| 285 | { | 
|---|
| 286 | profileIterator->First(); | 
|---|
| 287 | if (profileIterator->Is_Done()) | 
|---|
| 288 | return; | 
|---|
| 289 |  | 
|---|
| 290 | float accumulated_time=0,parent_time = profileIterator->Is_Root() ? CProfileManager::Get_Time_Since_Reset() : profileIterator->Get_Current_Parent_Total_Time(); | 
|---|
| 291 | int i; | 
|---|
| 292 | int frames_since_reset = CProfileManager::Get_Frame_Count_Since_Reset(); | 
|---|
| 293 | for (i=0;i<spacing;i++) printf("."); | 
|---|
| 294 | printf("----------------------------------\n"); | 
|---|
| 295 | for (i=0;i<spacing;i++) printf("."); | 
|---|
| 296 | printf("Profiling: %s (total running time: %.3f ms) ---\n",     profileIterator->Get_Current_Parent_Name(), parent_time ); | 
|---|
| 297 | float totalTime = 0.f; | 
|---|
| 298 |  | 
|---|
| 299 |  | 
|---|
| 300 | int numChildren = 0; | 
|---|
| 301 |  | 
|---|
| 302 | for (i = 0; !profileIterator->Is_Done(); i++,profileIterator->Next()) | 
|---|
| 303 | { | 
|---|
| 304 | numChildren++; | 
|---|
| 305 | float current_total_time = profileIterator->Get_Current_Total_Time(); | 
|---|
| 306 | accumulated_time += current_total_time; | 
|---|
| 307 | float fraction = parent_time > SIMD_EPSILON ? (current_total_time / parent_time) * 100 : 0.f; | 
|---|
| 308 | { | 
|---|
| 309 | int i;  for (i=0;i<spacing;i++) printf("."); | 
|---|
| 310 | } | 
|---|
| 311 | 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()); | 
|---|
| 312 | totalTime += current_total_time; | 
|---|
| 313 | //recurse into children | 
|---|
| 314 | } | 
|---|
| 315 |  | 
|---|
| 316 | if (parent_time < accumulated_time) | 
|---|
| 317 | { | 
|---|
| 318 | printf("what's wrong\n"); | 
|---|
| 319 | } | 
|---|
| 320 | for (i=0;i<spacing;i++) printf("."); | 
|---|
| 321 | printf("%s (%.3f %%) :: %.3f ms\n", "Unaccounted:",parent_time > SIMD_EPSILON ? ((parent_time - accumulated_time) / parent_time) * 100 : 0.f, parent_time - accumulated_time); | 
|---|
| 322 |  | 
|---|
| 323 | for (i=0;i<numChildren;i++) | 
|---|
| 324 | { | 
|---|
| 325 | profileIterator->Enter_Child(i); | 
|---|
| 326 | dumpRecursive(profileIterator,spacing+3); | 
|---|
| 327 | profileIterator->Enter_Parent(); | 
|---|
| 328 | } | 
|---|
| 329 | } | 
|---|
| 330 |  | 
|---|
| 331 |  | 
|---|
| 332 |  | 
|---|
| 333 | void    CProfileManager::dumpAll() | 
|---|
| 334 | { | 
|---|
| 335 | CProfileIterator* profileIterator = 0; | 
|---|
| 336 | profileIterator = CProfileManager::Get_Iterator(); | 
|---|
| 337 |  | 
|---|
| 338 | dumpRecursive(profileIterator,0); | 
|---|
| 339 |  | 
|---|
| 340 | CProfileManager::Release_Iterator(profileIterator); | 
|---|
| 341 | } | 
|---|
| 342 |  | 
|---|
| 343 |  | 
|---|
| 344 |  | 
|---|
| 345 | #endif //USE_BT_CLOCK | 
|---|
| 346 |  | 
|---|