extern/bullet/LinearMath/quickprof.h

   1 /************************************************************************
   2 * QuickProf                                                             *
   3 * Copyright (C) 2006                                                    *
   4 * Tyler Streeter  tylerstreeter@gmail.com                               *
   5 * All rights reserved.                                                  *
   6 * Web: http://quickprof.sourceforge.net                                 *
   7 *                                                                       *
   8 * This library is free software; you can redistribute it and/or         *
   9 * modify it under the terms of EITHER:                                  *
  10 *   (1) The GNU Lesser General Public License as published by the Free  *
  11 *       Software Foundation; either version 2.1 of the License, or (at  *
  12 *       your option) any later version. The text of the GNU Lesser      *
  13 *       General Public License is included with this library in the     *
  14 *       file license-LGPL.txt.                                          *
  15 *   (2) The BSD-style license that is included with this library in     *
  16 *       the file license-BSD.txt.                                       *
  17 *                                                                       *
  18 * This library is distributed in the hope that it will be useful,       *
  19 * but WITHOUT ANY WARRANTY; without even the implied warranty of        *
  20 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the files    *
  21 * license-LGPL.txt and license-BSD.txt for more details.                *
  22 ************************************************************************/
  23
  24 // Please visit the project website (http://quickprof.sourceforge.net)
  25 // for usage instructions.
  26
  27 // Credits: The Clock class was inspired by the Timer classes in
  28 // Ogre (www.ogre3d.org).
  29
  30
  31 //#define USE_QUICKPROF 1
  32
  33 #ifdef USE_QUICKPROF
  34
  35 #ifndef QUICK_PROF_H
  36 #define QUICK_PROF_H
  37
  38 #include <iostream>
  39 #include <fstream>
  40 #include <string>
  41 #include <map>
  42
  43 #ifdef __PPU__
  44 #include <sys/sys_time.h>
  45 #include <stdio.h>
  46 typedef uint64_t __int64;
  47 #endif
  48
  49 #if defined(WIN32) || defined(_WIN32)
  50         #define USE_WINDOWS_TIMERS
  51         #include <windows.h>
  52         #include <time.h>
  53 #else
  54         #include <sys/time.h>
  55 #endif
  56
  57 #define mymin(a,b) (a > b ? a : b)
  58 namespace hidden
  59 {
  60         /// A simple data structure representing a single timed block
  61         /// of code.
  62         struct ProfileBlock
  63         {
  64                 ProfileBlock()
  65                 {
  66                         currentBlockStartMicroseconds = 0;
  67                         currentCycleTotalMicroseconds = 0;
  68                         lastCycleTotalMicroseconds = 0;
  69                         totalMicroseconds = 0;
  70                 }
  71
  72                 /// The starting time (in us) of the current block update.
  73                 unsigned long int currentBlockStartMicroseconds;
  74
  75                 /// The accumulated time (in us) spent in this block during the
  76                 /// current profiling cycle.
  77                 unsigned long int currentCycleTotalMicroseconds;
  78
  79                 /// The accumulated time (in us) spent in this block during the
  80                 /// past profiling cycle.
  81                 unsigned long int lastCycleTotalMicroseconds;
  82
  83                 /// The total accumulated time (in us) spent in this block.
  84                 unsigned long int totalMicroseconds;
  85         };
  86
  87         class Clock
  88         {
  89         public:
  90                 Clock()
  91                 {
  92 #ifdef USE_WINDOWS_TIMERS
  93                         QueryPerformanceFrequency(&mClockFrequency);
  94 #endif
  95                         reset();
  96                 }
  97
  98                 ~Clock()
  99                 {
 100                 }
 101
 102                 /// Resets the initial reference time.
 103                 void reset()
 104                 {
 105 #ifdef USE_WINDOWS_TIMERS
 106                         QueryPerformanceCounter(&mStartTime);
 107                         mStartTick = GetTickCount();
 108                         mPrevElapsedTime = 0;
 109 #else
 110 #ifdef __PPU__
 111
 112         typedef uint64_t __int64;
 113         typedef __int64  ClockSize;
 114         ClockSize newTime;
 115         __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 116         mStartTime = newTime;
 117 #else
 118                         gettimeofday(&mStartTime, NULL);
 119 #endif
 120
 121 #endif
 122                 }
 123
 124                 /// Returns the time in ms since the last call to reset or since
 125                 /// the Clock was created.
 126                 unsigned long int getTimeMilliseconds()
 127                 {
 128 #ifdef USE_WINDOWS_TIMERS
 129                         LARGE_INTEGER currentTime;
 130                         QueryPerformanceCounter(&currentTime);
 131                         LONGLONG elapsedTime = currentTime.QuadPart -
 132                                 mStartTime.QuadPart;
 133
 134                         // Compute the number of millisecond ticks elapsed.
 135                         unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
 136                                 mClockFrequency.QuadPart);
 137
 138                         // Check for unexpected leaps in the Win32 performance counter.
 139                         // (This is caused by unexpected data across the PCI to ISA
 140                         // bridge, aka south bridge.  See Microsoft KB274323.)
 141                         unsigned long elapsedTicks = GetTickCount() - mStartTick;
 142                         signed long msecOff = (signed long)(msecTicks - elapsedTicks);
 143                         if (msecOff < -100 || msecOff > 100)
 144                         {
 145                                 // Adjust the starting time forwards.
 146                                 LONGLONG msecAdjustment = mymin(msecOff *
 147                                         mClockFrequency.QuadPart / 1000, elapsedTime -
 148                                         mPrevElapsedTime);
 149                                 mStartTime.QuadPart += msecAdjustment;
 150                                 elapsedTime -= msecAdjustment;
 151
 152                                 // Recompute the number of millisecond ticks elapsed.
 153                                 msecTicks = (unsigned long)(1000 * elapsedTime /
 154                                         mClockFrequency.QuadPart);
 155                         }
 156
 157                         // Store the current elapsed time for adjustments next time.
 158                         mPrevElapsedTime = elapsedTime;
 159
 160                         return msecTicks;
 161 #else
 162
 163 #ifdef __PPU__
 164         __int64 freq=sys_time_get_timebase_frequency();
 165          double dFreq=((double) freq) / 1000.0;
 166         typedef uint64_t __int64;
 167         typedef __int64  ClockSize;
 168         ClockSize newTime;
 169         __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 170
 171         return (newTime-mStartTime) / dFreq;
 172 #else
 173
 174                         struct timeval currentTime;
 175                         gettimeofday(&currentTime, NULL);
 176                         return (currentTime.tv_sec - mStartTime.tv_sec) * 1000 +
 177                                 (currentTime.tv_usec - mStartTime.tv_usec) / 1000;
 178 #endif //__PPU__
 179 #endif
 180                 }
 181
 182                 /// Returns the time in us since the last call to reset or since
 183                 /// the Clock was created.
 184                 unsigned long int getTimeMicroseconds()
 185                 {
 186 #ifdef USE_WINDOWS_TIMERS
 187                         LARGE_INTEGER currentTime;
 188                         QueryPerformanceCounter(&currentTime);
 189                         LONGLONG elapsedTime = currentTime.QuadPart -
 190                                 mStartTime.QuadPart;
 191
 192                         // Compute the number of millisecond ticks elapsed.
 193                         unsigned long msecTicks = (unsigned long)(1000 * elapsedTime /
 194                                 mClockFrequency.QuadPart);
 195
 196                         // Check for unexpected leaps in the Win32 performance counter.
 197                         // (This is caused by unexpected data across the PCI to ISA
 198                         // bridge, aka south bridge.  See Microsoft KB274323.)
 199                         unsigned long elapsedTicks = GetTickCount() - mStartTick;
 200                         signed long msecOff = (signed long)(msecTicks - elapsedTicks);
 201                         if (msecOff < -100 || msecOff > 100)
 202                         {
 203                                 // Adjust the starting time forwards.
 204                                 LONGLONG msecAdjustment = mymin(msecOff *
 205                                         mClockFrequency.QuadPart / 1000, elapsedTime -
 206                                         mPrevElapsedTime);
 207                                 mStartTime.QuadPart += msecAdjustment;
 208                                 elapsedTime -= msecAdjustment;
 209                         }
 210
 211                         // Store the current elapsed time for adjustments next time.
 212                         mPrevElapsedTime = elapsedTime;
 213
 214                         // Convert to microseconds.
 215                         unsigned long usecTicks = (unsigned long)(1000000 * elapsedTime /
 216                                 mClockFrequency.QuadPart);
 217
 218                         return usecTicks;
 219 #else
 220
 221 #ifdef __PPU__
 222         __int64 freq=sys_time_get_timebase_frequency();
 223          double dFreq=((double) freq)/ 1000000.0;
 224         typedef uint64_t __int64;
 225         typedef __int64  ClockSize;
 226         ClockSize newTime;
 227         __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory");
 228
 229         return (newTime-mStartTime) / dFreq;
 230 #else
 231
 232                         struct timeval currentTime;
 233                         gettimeofday(&currentTime, NULL);
 234                         return (currentTime.tv_sec - mStartTime.tv_sec) * 1000000 +
 235                                 (currentTime.tv_usec - mStartTime.tv_usec);
 236 #endif//__PPU__
 237 #endif
 238                 }
 239
 240         private:
 241 #ifdef USE_WINDOWS_TIMERS
 242                 LARGE_INTEGER mClockFrequency;
 243                 DWORD mStartTick;
 244                 LONGLONG mPrevElapsedTime;
 245                 LARGE_INTEGER mStartTime;
 246 #else
 247 #ifdef __PPU__
 248                 uint64_t        mStartTime;
 249 #else
 250                 struct timeval mStartTime;
 251 #endif
 252 #endif //__PPU__
 253
 254         };
 255 };
 256
 257 /// A static class that manages timing for a set of profiling blocks.
 258 class Profiler
 259 {
 260 public:
 261         /// A set of ways to retrieve block timing data.
 262         enum BlockTimingMethod
 263         {
 264                 /// The total time spent in the block (in seconds) since the
 265                 /// profiler was initialized.
 266                 BLOCK_TOTAL_SECONDS,
 267
 268                 /// The total time spent in the block (in ms) since the
 269                 /// profiler was initialized.
 270                 BLOCK_TOTAL_MILLISECONDS,
 271
 272                 /// The total time spent in the block (in us) since the
 273                 /// profiler was initialized.
 274                 BLOCK_TOTAL_MICROSECONDS,
 275
 276                 /// The total time spent in the block, as a % of the total
 277                 /// elapsed time since the profiler was initialized.
 278                 BLOCK_TOTAL_PERCENT,
 279
 280                 /// The time spent in the block (in seconds) in the most recent
 281                 /// profiling cycle.
 282                 BLOCK_CYCLE_SECONDS,
 283
 284                 /// The time spent in the block (in ms) in the most recent
 285                 /// profiling cycle.
 286                 BLOCK_CYCLE_MILLISECONDS,
 287
 288                 /// The time spent in the block (in us) in the most recent
 289                 /// profiling cycle.
 290                 BLOCK_CYCLE_MICROSECONDS,
 291
 292                 /// The time spent in the block (in seconds) in the most recent
 293                 /// profiling cycle, as a % of the total cycle time.
 294                 BLOCK_CYCLE_PERCENT
 295         };
 296
 297         /// Initializes the profiler.  This must be called first.  If this is
 298         /// never called, the profiler is effectively disabled; all other
 299         /// functions will return immediately.  The first parameter
 300         /// is the name of an output data file; if this string is not empty,
 301         /// data will be saved on every profiling cycle; if this string is
 302         /// empty, no data will be saved to a file.  The second parameter
 303         /// determines which timing method is used when printing data to the
 304         /// output file.
 305         inline static void init(const std::string outputFilename="",
 306                 BlockTimingMethod outputMethod=BLOCK_CYCLE_MILLISECONDS);
 307
 308         /// Cleans up allocated memory.
 309         inline static void destroy();
 310
 311         /// Begins timing the named block of code.
 312         inline static void beginBlock(const std::string& name);
 313
 314         /// Updates the accumulated time spent in the named block by adding
 315         /// the elapsed time since the last call to startBlock for this block
 316         /// name.
 317         inline static void endBlock(const std::string& name);
 318
 319         /// Returns the time spent in the named block according to the
 320         /// given timing method.  See comments on BlockTimingMethod for details.
 321         inline static double getBlockTime(const std::string& name,
 322                 BlockTimingMethod method=BLOCK_CYCLE_MILLISECONDS);
 323
 324         /// Defines the end of a profiling cycle.  Use this regularly if you
 325         /// want to generate detailed timing information.  This must not be
 326         /// called within a timing block.
 327         inline static void endProfilingCycle();
 328
 329         /// A helper function that creates a string of statistics for
 330         /// each timing block.  This is mainly for printing an overall
 331         /// summary to the command line.
 332         inline static std::string createStatsString(
 333                 BlockTimingMethod method=BLOCK_TOTAL_PERCENT);
 334
 335 //private:
 336         inline Profiler();
 337
 338         inline ~Profiler();
 339
 340         /// Prints an error message to standard output.
 341         inline static void printError(const std::string& msg)
 342         {
 343                 std::cout << "[QuickProf error] " << msg << std::endl;
 344         }
 345
 346         /// Determines whether the profiler is enabled.
 347         static bool mEnabled;
 348
 349         /// The clock used to time profile blocks.
 350         static hidden::Clock mClock;
 351
 352         /// The starting time (in us) of the current profiling cycle.
 353         static unsigned long int mCurrentCycleStartMicroseconds;
 354
 355         /// The duration (in us) of the most recent profiling cycle.
 356         static unsigned long int mLastCycleDurationMicroseconds;
 357
 358         /// Internal map of named profile blocks.
 359         static std::map<std::string, hidden::ProfileBlock*> mProfileBlocks;
 360
 361         /// The data file used if this feature is enabled in 'init.'
 362         static std::ofstream mOutputFile;
 363
 364         /// Tracks whether we have begun print data to the output file.
 365         static bool mFirstFileOutput;
 366
 367         /// The method used when printing timing data to an output file.
 368         static BlockTimingMethod mFileOutputMethod;
 369
 370         /// The number of the current profiling cycle.
 371         static unsigned long int mCycleNumber;
 372 };
 373
 374
 375 Profiler::Profiler()
 376 {
 377         // This never gets called because a Profiler instance is never
 378         // created.
 379 }
 380
 381 Profiler::~Profiler()
 382 {
 383         // This never gets called because a Profiler instance is never
 384         // created.
 385 }
 386
 387 void Profiler::init(const std::string outputFilename,
 388         BlockTimingMethod outputMethod)
 389 {
 390         mEnabled = true;
 391
 392         if (!outputFilename.empty())
 393         {
 394                 mOutputFile.open(outputFilename.c_str());
 395         }
 396
 397         mFileOutputMethod = outputMethod;
 398
 399         mClock.reset();
 400
 401         // Set the start time for the first cycle.
 402         mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds();
 403 }
 404
 405 void Profiler::destroy()
 406 {
 407         if (!mEnabled)
 408         {
 409                 return;
 410         }
 411
 412         if (mOutputFile.is_open())
 413         {
 414                 mOutputFile.close();
 415         }
 416
 417         // Destroy all ProfileBlocks.
 418         while (!mProfileBlocks.empty())
 419         {
 420                 delete (*mProfileBlocks.begin()).second;
 421                 mProfileBlocks.erase(mProfileBlocks.begin());
 422         }
 423 }
 424
 425 void Profiler::beginBlock(const std::string& name)
 426 {
 427         if (!mEnabled)
 428         {
 429                 return;
 430         }
 431
 432         if (name.empty())
 433         {
 434                 printError("Cannot allow unnamed profile blocks.");
 435                 return;
 436         }
 437
 438         hidden::ProfileBlock* block = mProfileBlocks[name];
 439
 440         if (!block)
 441         {
 442                 // Create a new ProfileBlock.
 443                 mProfileBlocks[name] = new hidden::ProfileBlock();
 444                 block = mProfileBlocks[name];
 445         }
 446
 447         // We do this at the end to get more accurate results.
 448         block->currentBlockStartMicroseconds = mClock.getTimeMicroseconds();
 449 }
 450
 451 void Profiler::endBlock(const std::string& name)
 452 {
 453         if (!mEnabled)
 454         {
 455                 return;
 456         }
 457
 458         // We do this at the beginning to get more accurate results.
 459         unsigned long int endTick = mClock.getTimeMicroseconds();
 460
 461         hidden::ProfileBlock* block = mProfileBlocks[name];
 462
 463         if (!block)
 464         {
 465                 // The named block does not exist.  Print an error.
 466                 printError("The profile block named '" + name +
 467                         "' does not exist.");
 468                 return;
 469         }
 470
 471         unsigned long int blockDuration = endTick -
 472                 block->currentBlockStartMicroseconds;
 473         block->currentCycleTotalMicroseconds += blockDuration;
 474         block->totalMicroseconds += blockDuration;
 475 }
 476
 477 double Profiler::getBlockTime(const std::string& name,
 478         BlockTimingMethod method)
 479 {
 480         if (!mEnabled)
 481         {
 482                 return 0;
 483         }
 484
 485         hidden::ProfileBlock* block = mProfileBlocks[name];
 486
 487         if (!block)
 488         {
 489                 // The named block does not exist.  Print an error.
 490                 printError("The profile block named '" + name +
 491                         "' does not exist.");
 492                 return 0;
 493         }
 494
 495         double result = 0;
 496
 497         switch(method)
 498         {
 499                 case BLOCK_TOTAL_SECONDS:
 500                         result = (double)block->totalMicroseconds * (double)0.000001;
 501                         break;
 502                 case BLOCK_TOTAL_MILLISECONDS:
 503                         result = (double)block->totalMicroseconds * (double)0.001;
 504                         break;
 505                 case BLOCK_TOTAL_MICROSECONDS:
 506                         result = (double)block->totalMicroseconds;
 507                         break;
 508                 case BLOCK_TOTAL_PERCENT:
 509                 {
 510                         double timeSinceInit = (double)mClock.getTimeMicroseconds();
 511                         if (timeSinceInit <= 0)
 512                         {
 513                                 result = 0;
 514                         }
 515                         else
 516                         {
 517                                 result = 100.0 * (double)block->totalMicroseconds /
 518                                         timeSinceInit;
 519                         }
 520                         break;
 521                 }
 522                 case BLOCK_CYCLE_SECONDS:
 523                         result = (double)block->lastCycleTotalMicroseconds *
 524                                 (double)0.000001;
 525                         break;
 526                 case BLOCK_CYCLE_MILLISECONDS:
 527                         result = (double)block->lastCycleTotalMicroseconds *
 528                                 (double)0.001;
 529                         break;
 530                 case BLOCK_CYCLE_MICROSECONDS:
 531                         result = (double)block->lastCycleTotalMicroseconds;
 532                         break;
 533                 case BLOCK_CYCLE_PERCENT:
 534                 {
 535                         if (0 == mLastCycleDurationMicroseconds)
 536                         {
 537                                 // We have not yet finished a cycle, so just return zero
 538                                 // percent to avoid a divide by zero error.
 539                                 result = 0;
 540                         }
 541                         else
 542                         {
 543                                 result = 100.0 * (double)block->lastCycleTotalMicroseconds /
 544                                         mLastCycleDurationMicroseconds;
 545                         }
 546                         break;
 547                 }
 548                 default:
 549                         break;
 550         }
 551
 552         return result;
 553 }
 554
 555 void Profiler::endProfilingCycle()
 556 {
 557         if (!mEnabled)
 558         {
 559                 return;
 560         }
 561
 562         // Store the duration of the cycle that just finished.
 563         mLastCycleDurationMicroseconds = mClock.getTimeMicroseconds() -
 564                 mCurrentCycleStartMicroseconds;
 565
 566         // For each block, update data for the cycle that just finished.
 567         std::map<std::string, hidden::ProfileBlock*>::iterator iter;
 568         for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter)
 569         {
 570                 hidden::ProfileBlock* block = (*iter).second;
 571                 block->lastCycleTotalMicroseconds =
 572                         block->currentCycleTotalMicroseconds;
 573                 block->currentCycleTotalMicroseconds = 0;
 574         }
 575
 576         if (mOutputFile.is_open())
 577         {
 578                 // Print data to the output file.
 579                 if (mFirstFileOutput)
 580                 {
 581                         // On the first iteration, print a header line that shows the
 582                         // names of each profiling block.
 583                         mOutputFile << "#cycle; ";
 584
 585                         for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end();
 586                                 ++iter)
 587                         {
 588                                 mOutputFile << (*iter).first << "; ";
 589                         }
 590
 591                         mOutputFile << std::endl;
 592                         mFirstFileOutput = false;
 593                 }
 594
 595                 mOutputFile << mCycleNumber << "; ";
 596
 597                 for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end();
 598                         ++iter)
 599                 {
 600                         mOutputFile << getBlockTime((*iter).first, mFileOutputMethod)
 601                                 << "; ";
 602                 }
 603
 604                 mOutputFile << std::endl;
 605         }
 606
 607         ++mCycleNumber;
 608         mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds();
 609 }
 610
 611 std::string Profiler::createStatsString(BlockTimingMethod method)
 612 {
 613         if (!mEnabled)
 614         {
 615                 return "";
 616         }
 617
 618         std::string s;
 619         std::string suffix;
 620
 621         switch(method)
 622         {
 623                 case BLOCK_TOTAL_SECONDS:
 624                         suffix = "s";
 625                         break;
 626                 case BLOCK_TOTAL_MILLISECONDS:
 627                         suffix = "ms";
 628                         break;
 629                 case BLOCK_TOTAL_MICROSECONDS:
 630                         suffix = "us";
 631                         break;
 632                 case BLOCK_TOTAL_PERCENT:
 633                 {
 634                         suffix = "%";
 635                         break;
 636                 }
 637                 case BLOCK_CYCLE_SECONDS:
 638                         suffix = "s";
 639                         break;
 640                 case BLOCK_CYCLE_MILLISECONDS:
 641                         suffix = "ms";
 642                         break;
 643                 case BLOCK_CYCLE_MICROSECONDS:
 644                         suffix = "us";
 645                         break;
 646                 case BLOCK_CYCLE_PERCENT:
 647                 {
 648                         suffix = "%";
 649                         break;
 650                 }
 651                 default:
 652                         break;
 653         }
 654
 655         std::map<std::string, hidden::ProfileBlock*>::iterator iter;
 656         for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter)
 657         {
 658                 if (iter != mProfileBlocks.begin())
 659                 {
 660                         s += "\n";
 661                 }
 662
 663                 char blockTime[64];
 664                 sprintf(blockTime, "%lf", getBlockTime((*iter).first, method));
 665
 666                 s += (*iter).first;
 667                 s += ": ";
 668                 s += blockTime;
 669                 s += " ";
 670                 s += suffix;
 671         }
 672
 673         return s;
 674 }
 675
 676 #endif
 677
 678 #endif //USE_QUICKPROF