/************************************************************************ * QuickProf * * Copyright (C) 2006 * * Tyler Streeter tylerstreeter@gmail.com * * All rights reserved. * * Web: http://quickprof.sourceforge.net * * * * This library is free software; you can redistribute it and/or * * modify it under the terms of EITHER: * * (1) The GNU Lesser General Public License as published by the Free * * Software Foundation; either version 2.1 of the License, or (at * * your option) any later version. The text of the GNU Lesser * * General Public License is included with this library in the * * file license-LGPL.txt. * * (2) The BSD-style license that is included with this library in * * the file license-BSD.txt. * * * * This library is distributed in the hope that it will be useful, * * but WITHOUT ANY WARRANTY; without even the implied warranty of * * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the files * * license-LGPL.txt and license-BSD.txt for more details. * ************************************************************************/ // Please visit the project website (http://quickprof.sourceforge.net) // for usage instructions. // Credits: The Clock class was inspired by the Timer classes in // Ogre (www.ogre3d.org). //#define USE_QUICKPROF 1 #ifdef USE_QUICKPROF #ifndef QUICK_PROF_H #define QUICK_PROF_H #include #include #include #include #ifdef __PPU__ #include #include typedef uint64_t __int64; #endif #if defined(WIN32) || defined(_WIN32) #define USE_WINDOWS_TIMERS #include #include #else #include #endif #define mymin(a,b) (a > b ? a : b) namespace hidden { /// A simple data structure representing a single timed block /// of code. struct ProfileBlock { ProfileBlock() { currentBlockStartMicroseconds = 0; currentCycleTotalMicroseconds = 0; lastCycleTotalMicroseconds = 0; totalMicroseconds = 0; } /// The starting time (in us) of the current block update. unsigned long int currentBlockStartMicroseconds; /// The accumulated time (in us) spent in this block during the /// current profiling cycle. unsigned long int currentCycleTotalMicroseconds; /// The accumulated time (in us) spent in this block during the /// past profiling cycle. unsigned long int lastCycleTotalMicroseconds; /// The total accumulated time (in us) spent in this block. unsigned long int totalMicroseconds; }; class Clock { public: Clock() { #ifdef USE_WINDOWS_TIMERS QueryPerformanceFrequency(&mClockFrequency); #endif reset(); } ~Clock() { } /// Resets the initial reference time. void reset() { #ifdef USE_WINDOWS_TIMERS QueryPerformanceCounter(&mStartTime); mStartTick = GetTickCount(); mPrevElapsedTime = 0; #else #ifdef __PPU__ typedef uint64_t __int64; typedef __int64 ClockSize; ClockSize newTime; __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory"); mStartTime = newTime; #else gettimeofday(&mStartTime, NULL); #endif #endif } /// Returns the time in ms since the last call to reset or since /// the Clock was created. unsigned long int getTimeMilliseconds() { #ifdef USE_WINDOWS_TIMERS LARGE_INTEGER currentTime; QueryPerformanceCounter(¤tTime); LONGLONG elapsedTime = currentTime.QuadPart - mStartTime.QuadPart; // Compute the number of millisecond ticks elapsed. unsigned long msecTicks = (unsigned long)(1000 * elapsedTime / mClockFrequency.QuadPart); // Check for unexpected leaps in the Win32 performance counter. // (This is caused by unexpected data across the PCI to ISA // bridge, aka south bridge. See Microsoft KB274323.) unsigned long elapsedTicks = GetTickCount() - mStartTick; signed long msecOff = (signed long)(msecTicks - elapsedTicks); if (msecOff < -100 || msecOff > 100) { // Adjust the starting time forwards. LONGLONG msecAdjustment = mymin(msecOff * mClockFrequency.QuadPart / 1000, elapsedTime - mPrevElapsedTime); mStartTime.QuadPart += msecAdjustment; elapsedTime -= msecAdjustment; // Recompute the number of millisecond ticks elapsed. msecTicks = (unsigned long)(1000 * elapsedTime / mClockFrequency.QuadPart); } // Store the current elapsed time for adjustments next time. mPrevElapsedTime = elapsedTime; return msecTicks; #else #ifdef __PPU__ __int64 freq=sys_time_get_timebase_frequency(); double dFreq=((double) freq) / 1000.0; typedef uint64_t __int64; typedef __int64 ClockSize; ClockSize newTime; __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory"); return (newTime-mStartTime) / dFreq; #else struct timeval currentTime; gettimeofday(¤tTime, NULL); return (currentTime.tv_sec - mStartTime.tv_sec) * 1000 + (currentTime.tv_usec - mStartTime.tv_usec) / 1000; #endif //__PPU__ #endif } /// Returns the time in us since the last call to reset or since /// the Clock was created. unsigned long int getTimeMicroseconds() { #ifdef USE_WINDOWS_TIMERS LARGE_INTEGER currentTime; QueryPerformanceCounter(¤tTime); LONGLONG elapsedTime = currentTime.QuadPart - mStartTime.QuadPart; // Compute the number of millisecond ticks elapsed. unsigned long msecTicks = (unsigned long)(1000 * elapsedTime / mClockFrequency.QuadPart); // Check for unexpected leaps in the Win32 performance counter. // (This is caused by unexpected data across the PCI to ISA // bridge, aka south bridge. See Microsoft KB274323.) unsigned long elapsedTicks = GetTickCount() - mStartTick; signed long msecOff = (signed long)(msecTicks - elapsedTicks); if (msecOff < -100 || msecOff > 100) { // Adjust the starting time forwards. LONGLONG msecAdjustment = mymin(msecOff * mClockFrequency.QuadPart / 1000, elapsedTime - mPrevElapsedTime); mStartTime.QuadPart += msecAdjustment; elapsedTime -= msecAdjustment; } // Store the current elapsed time for adjustments next time. mPrevElapsedTime = elapsedTime; // Convert to microseconds. unsigned long usecTicks = (unsigned long)(1000000 * elapsedTime / mClockFrequency.QuadPart); return usecTicks; #else #ifdef __PPU__ __int64 freq=sys_time_get_timebase_frequency(); double dFreq=((double) freq)/ 1000000.0; typedef uint64_t __int64; typedef __int64 ClockSize; ClockSize newTime; __asm __volatile__( "mftb %0" : "=r" (newTime) : : "memory"); return (newTime-mStartTime) / dFreq; #else struct timeval currentTime; gettimeofday(¤tTime, NULL); return (currentTime.tv_sec - mStartTime.tv_sec) * 1000000 + (currentTime.tv_usec - mStartTime.tv_usec); #endif//__PPU__ #endif } private: #ifdef USE_WINDOWS_TIMERS LARGE_INTEGER mClockFrequency; DWORD mStartTick; LONGLONG mPrevElapsedTime; LARGE_INTEGER mStartTime; #else #ifdef __PPU__ uint64_t mStartTime; #else struct timeval mStartTime; #endif #endif //__PPU__ }; }; /// A static class that manages timing for a set of profiling blocks. class Profiler { public: /// A set of ways to retrieve block timing data. enum BlockTimingMethod { /// The total time spent in the block (in seconds) since the /// profiler was initialized. BLOCK_TOTAL_SECONDS, /// The total time spent in the block (in ms) since the /// profiler was initialized. BLOCK_TOTAL_MILLISECONDS, /// The total time spent in the block (in us) since the /// profiler was initialized. BLOCK_TOTAL_MICROSECONDS, /// The total time spent in the block, as a % of the total /// elapsed time since the profiler was initialized. BLOCK_TOTAL_PERCENT, /// The time spent in the block (in seconds) in the most recent /// profiling cycle. BLOCK_CYCLE_SECONDS, /// The time spent in the block (in ms) in the most recent /// profiling cycle. BLOCK_CYCLE_MILLISECONDS, /// The time spent in the block (in us) in the most recent /// profiling cycle. BLOCK_CYCLE_MICROSECONDS, /// The time spent in the block (in seconds) in the most recent /// profiling cycle, as a % of the total cycle time. BLOCK_CYCLE_PERCENT }; /// Initializes the profiler. This must be called first. If this is /// never called, the profiler is effectively disabled; all other /// functions will return immediately. The first parameter /// is the name of an output data file; if this string is not empty, /// data will be saved on every profiling cycle; if this string is /// empty, no data will be saved to a file. The second parameter /// determines which timing method is used when printing data to the /// output file. inline static void init(const std::string outputFilename="", BlockTimingMethod outputMethod=BLOCK_CYCLE_MILLISECONDS); /// Cleans up allocated memory. inline static void destroy(); /// Begins timing the named block of code. inline static void beginBlock(const std::string& name); /// Updates the accumulated time spent in the named block by adding /// the elapsed time since the last call to startBlock for this block /// name. inline static void endBlock(const std::string& name); /// Returns the time spent in the named block according to the /// given timing method. See comments on BlockTimingMethod for details. inline static double getBlockTime(const std::string& name, BlockTimingMethod method=BLOCK_CYCLE_MILLISECONDS); /// Defines the end of a profiling cycle. Use this regularly if you /// want to generate detailed timing information. This must not be /// called within a timing block. inline static void endProfilingCycle(); /// A helper function that creates a string of statistics for /// each timing block. This is mainly for printing an overall /// summary to the command line. inline static std::string createStatsString( BlockTimingMethod method=BLOCK_TOTAL_PERCENT); //private: inline Profiler(); inline ~Profiler(); /// Prints an error message to standard output. inline static void printError(const std::string& msg) { std::cout << "[QuickProf error] " << msg << std::endl; } /// Determines whether the profiler is enabled. static bool mEnabled; /// The clock used to time profile blocks. static hidden::Clock mClock; /// The starting time (in us) of the current profiling cycle. static unsigned long int mCurrentCycleStartMicroseconds; /// The duration (in us) of the most recent profiling cycle. static unsigned long int mLastCycleDurationMicroseconds; /// Internal map of named profile blocks. static std::map mProfileBlocks; /// The data file used if this feature is enabled in 'init.' static std::ofstream mOutputFile; /// Tracks whether we have begun print data to the output file. static bool mFirstFileOutput; /// The method used when printing timing data to an output file. static BlockTimingMethod mFileOutputMethod; /// The number of the current profiling cycle. static unsigned long int mCycleNumber; }; Profiler::Profiler() { // This never gets called because a Profiler instance is never // created. } Profiler::~Profiler() { // This never gets called because a Profiler instance is never // created. } void Profiler::init(const std::string outputFilename, BlockTimingMethod outputMethod) { mEnabled = true; if (!outputFilename.empty()) { mOutputFile.open(outputFilename.c_str()); } mFileOutputMethod = outputMethod; mClock.reset(); // Set the start time for the first cycle. mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds(); } void Profiler::destroy() { if (!mEnabled) { return; } if (mOutputFile.is_open()) { mOutputFile.close(); } // Destroy all ProfileBlocks. while (!mProfileBlocks.empty()) { delete (*mProfileBlocks.begin()).second; mProfileBlocks.erase(mProfileBlocks.begin()); } } void Profiler::beginBlock(const std::string& name) { if (!mEnabled) { return; } if (name.empty()) { printError("Cannot allow unnamed profile blocks."); return; } hidden::ProfileBlock* block = mProfileBlocks[name]; if (!block) { // Create a new ProfileBlock. mProfileBlocks[name] = new hidden::ProfileBlock(); block = mProfileBlocks[name]; } // We do this at the end to get more accurate results. block->currentBlockStartMicroseconds = mClock.getTimeMicroseconds(); } void Profiler::endBlock(const std::string& name) { if (!mEnabled) { return; } // We do this at the beginning to get more accurate results. unsigned long int endTick = mClock.getTimeMicroseconds(); hidden::ProfileBlock* block = mProfileBlocks[name]; if (!block) { // The named block does not exist. Print an error. printError("The profile block named '" + name + "' does not exist."); return; } unsigned long int blockDuration = endTick - block->currentBlockStartMicroseconds; block->currentCycleTotalMicroseconds += blockDuration; block->totalMicroseconds += blockDuration; } double Profiler::getBlockTime(const std::string& name, BlockTimingMethod method) { if (!mEnabled) { return 0; } hidden::ProfileBlock* block = mProfileBlocks[name]; if (!block) { // The named block does not exist. Print an error. printError("The profile block named '" + name + "' does not exist."); return 0; } double result = 0; switch(method) { case BLOCK_TOTAL_SECONDS: result = (double)block->totalMicroseconds * (double)0.000001; break; case BLOCK_TOTAL_MILLISECONDS: result = (double)block->totalMicroseconds * (double)0.001; break; case BLOCK_TOTAL_MICROSECONDS: result = (double)block->totalMicroseconds; break; case BLOCK_TOTAL_PERCENT: { double timeSinceInit = (double)mClock.getTimeMicroseconds(); if (timeSinceInit <= 0) { result = 0; } else { result = 100.0 * (double)block->totalMicroseconds / timeSinceInit; } break; } case BLOCK_CYCLE_SECONDS: result = (double)block->lastCycleTotalMicroseconds * (double)0.000001; break; case BLOCK_CYCLE_MILLISECONDS: result = (double)block->lastCycleTotalMicroseconds * (double)0.001; break; case BLOCK_CYCLE_MICROSECONDS: result = (double)block->lastCycleTotalMicroseconds; break; case BLOCK_CYCLE_PERCENT: { if (0 == mLastCycleDurationMicroseconds) { // We have not yet finished a cycle, so just return zero // percent to avoid a divide by zero error. result = 0; } else { result = 100.0 * (double)block->lastCycleTotalMicroseconds / mLastCycleDurationMicroseconds; } break; } default: break; } return result; } void Profiler::endProfilingCycle() { if (!mEnabled) { return; } // Store the duration of the cycle that just finished. mLastCycleDurationMicroseconds = mClock.getTimeMicroseconds() - mCurrentCycleStartMicroseconds; // For each block, update data for the cycle that just finished. std::map::iterator iter; for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter) { hidden::ProfileBlock* block = (*iter).second; block->lastCycleTotalMicroseconds = block->currentCycleTotalMicroseconds; block->currentCycleTotalMicroseconds = 0; } if (mOutputFile.is_open()) { // Print data to the output file. if (mFirstFileOutput) { // On the first iteration, print a header line that shows the // names of each profiling block. mOutputFile << "#cycle; "; for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter) { mOutputFile << (*iter).first << "; "; } mOutputFile << std::endl; mFirstFileOutput = false; } mOutputFile << mCycleNumber << "; "; for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter) { mOutputFile << getBlockTime((*iter).first, mFileOutputMethod) << "; "; } mOutputFile << std::endl; } ++mCycleNumber; mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds(); } std::string Profiler::createStatsString(BlockTimingMethod method) { if (!mEnabled) { return ""; } std::string s; std::string suffix; switch(method) { case BLOCK_TOTAL_SECONDS: suffix = "s"; break; case BLOCK_TOTAL_MILLISECONDS: suffix = "ms"; break; case BLOCK_TOTAL_MICROSECONDS: suffix = "us"; break; case BLOCK_TOTAL_PERCENT: { suffix = "%"; break; } case BLOCK_CYCLE_SECONDS: suffix = "s"; break; case BLOCK_CYCLE_MILLISECONDS: suffix = "ms"; break; case BLOCK_CYCLE_MICROSECONDS: suffix = "us"; break; case BLOCK_CYCLE_PERCENT: { suffix = "%"; break; } default: break; } std::map::iterator iter; for (iter = mProfileBlocks.begin(); iter != mProfileBlocks.end(); ++iter) { if (iter != mProfileBlocks.begin()) { s += "\n"; } char blockTime[64]; sprintf(blockTime, "%lf", getBlockTime((*iter).first, method)); s += (*iter).first; s += ": "; s += blockTime; s += " "; s += suffix; } return s; } #endif #endif //USE_QUICKPROF