Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP
Fetching contributors…

Cannot retrieve contributors at this time

908 lines (776 sloc) 24.24 kB
/************************************************************************
* QuickProf *
* http://quickprof.sourceforge.net *
* Copyright (C) 2006-2008 *
* Tyler Streeter (http://www.tylerstreeter.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. *
* (3) The zlib/libpng license that is included with this library in *
* the file license-zlib-libpng.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, license-BSD.txt, and license-zlib-libpng.txt for *
* more details. *
************************************************************************/
// Please visit the project website (http://quickprof.sourceforge.net)
// for usage instructions.
#ifndef _QUICK_PROF_H_
#define _QUICK_PROF_H_
#include <iostream>
#include <fstream>
#include <sstream>
#include <map>
#include <math.h>
#if defined(WIN32) || defined(_WIN32)
#define USE_WINDOWS_TIMERS
#include <windows.h>
#include <time.h>
#else
#include <sys/time.h>
#endif
/// Use this macro to access the profiler singleton. For example:
/// PROFILER.init();
/// ...
/// PROFILER.beginBlock("foo");
/// foo();
/// PROFILER.endBlock("foo");
#define PROFILER quickprof::Profiler::instance()
/// The main namespace that contains everything.
namespace quickprof
{
/// A simple data structure representing a single timed block
/// of code.
struct ProfileBlock
{
ProfileBlock()
{
currentBlockStartMicroseconds = 0;
currentCycleTotalMicroseconds = 0;
avgCycleTotalMicroseconds = 0;
totalMicroseconds = 0;
}
/// The starting time (in us) of the current block update.
unsigned long long int currentBlockStartMicroseconds;
/// The accumulated time (in us) spent in this block during the
/// current profiling cycle.
unsigned long long int currentCycleTotalMicroseconds;
/// The accumulated time (in us) spent in this block during the
/// past profiling cycle.
double avgCycleTotalMicroseconds;
/// The total accumulated time (in us) spent in this block.
unsigned long long int totalMicroseconds;
};
/// A cross-platform clock class inspired by the Timer classes in
/// Ogre (http://www.ogre3d.org).
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();
mPrevClockCycles = 0;
#else
gettimeofday(&mStartTime, NULL);
#endif
}
/**
Returns the time in us since the last call to reset or since
the Clock was created.
@return The requested time in microseconds. Assuming 64-bit
integers are available, the return value is valid for 2^63
clock cycles (over 104 years w/ clock frequency 2.8 GHz).
*/
unsigned long long int getTimeMicroseconds()
{
#ifdef USE_WINDOWS_TIMERS
// Compute the number of elapsed clock cycles since the
// clock was created/reset. Using 64-bit signed ints, this
// is valid for 2^63 clock cycles (over 104 years w/ clock
// frequency 2.8 GHz).
LARGE_INTEGER currentTime;
QueryPerformanceCounter(&currentTime);
LONGLONG clockCycles = currentTime.QuadPart -
mStartTime.QuadPart;
// Compute the total elapsed seconds. This is valid for 2^63
// clock cycles (over 104 years w/ clock frequency 2.8 GHz).
LONGLONG sec = clockCycles / 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.) Avoid
// the problem with GetTickCount() wrapping to zero after 47
// days (because it uses 32-bit unsigned ints to represent
// milliseconds).
LONGLONG msec1 = sec * 1000 + (clockCycles - sec *
mClockFrequency.QuadPart) * 1000 / mClockFrequency.QuadPart;
DWORD tickCount = GetTickCount();
if (tickCount < mStartTick)
{
mStartTick = tickCount;
}
LONGLONG msec2 = (LONGLONG)(tickCount - mStartTick);
LONGLONG msecDiff = msec1 - msec2;
if (msecDiff < -100 || msecDiff > 100)
{
// Adjust the starting time forwards.
LONGLONG adjustment = (std::min)(msecDiff *
mClockFrequency.QuadPart / 1000, clockCycles -
mPrevClockCycles);
mStartTime.QuadPart += adjustment;
clockCycles -= adjustment;
// Update the measured seconds with the adjustments.
sec = clockCycles / mClockFrequency.QuadPart;
}
// Compute the milliseconds part. This is always valid since
// it will never be greater than 1000000.
LONGLONG usec = (clockCycles - sec * mClockFrequency.QuadPart) *
1000000 / mClockFrequency.QuadPart;
// Store the current elapsed clock cycles for adjustments next
// time.
mPrevClockCycles = clockCycles;
// The return value here is valid for 2^63 clock cycles (over
// 104 years w/ clock frequency 2.8 GHz).
return sec * 1000000 + usec;
#else
// Assuming signed 32-bit integers for tv_sec and tv_usec, and
// casting the seconds difference to a 64-bit unsigned long long
// int, the return value here is valid for over 136 years.
struct timeval currentTime;
gettimeofday(&currentTime, NULL);
return (unsigned long long int)(currentTime.tv_sec -
mStartTime.tv_sec) * 1000000 + (currentTime.tv_usec -
mStartTime.tv_usec);
#endif
}
private:
#ifdef USE_WINDOWS_TIMERS
LARGE_INTEGER mClockFrequency;
DWORD mStartTick;
LONGLONG mPrevClockCycles;
LARGE_INTEGER mStartTime;
#else
struct timeval mStartTime;
#endif
};
/// A set of ways to represent timing results.
enum TimeFormat
{
SECONDS,
MILLISECONDS,
MICROSECONDS,
PERCENT
};
/// A singleton class that manages timing for a set of profiling blocks.
class Profiler
{
public:
/**
Useful for creating multiple Profiler instances.
Normally the Profiler class should be accessed only through the
singleton instance method, which provides global access to a single
static Profiler instance. However, it is also possible to create
several local Profiler instances, if necessary.
*/
inline Profiler();
inline ~Profiler();
/**
Accesses the singleton instance.
@return The Profiler instance.
*/
inline static Profiler& instance();
/**
Initializes the profiler.
This must be called first. If this is never called, the profiler
is effectively disabled, and all other functions will return
immediately. This can be called more than once to re-initialize the
profiler, which erases all previous profiling block names and their
timing data.
@param smoothing The measured duration for each profile
block can be averaged across multiple
cycles, and this parameter defines the
smoothness of this averaging process.
The higher the value, the smoother the
resulting average durations will appear.
Leaving it at zero will essentially
disable the smoothing effect. More
specifically, this parameter is a time
constant (defined in terms of cycles) that
defines an exponentially-weighted moving
average. For example, a value of 4.0
means the past four cycles will contribute
63% of the current weighted average. This
value must be >= 0.
@param outputFilename If defined, enables timing data to be
printed to a data file for later analysis.
@param printPeriod Defines how often data is printed to the
file, in number of profiling cycles. For
example, set this to 1 if you want data
printed after each cycle, or 5 if you want
it printed every 5 cycles. It is a good
idea to increase this if you don't want
huge data files. Keep in mind, however,
that when you increase this, you might
want to increase the smoothing
parameter. (A good heuristic is to set
the smoothing parameter equal to the
print period.) This value must be >= 1.
@param printFormat Defines the format used when printing data
to a file.
*/
inline void init(double smoothing=0.0,
const std::string outputFilename="", size_t printPeriod=1,
TimeFormat printFormat=MILLISECONDS);
/**
Begins timing the named block of code.
@param name The name of the block.
*/
inline void beginBlock(const std::string& name);
/**
Defines the end of the named timing block.
@param name The name of the block.
*/
inline void endBlock(const std::string& name);
/**
Defines the end of a profiling cycle.
Use this regularly by calling it at the end of all timing blocks.
This is necessary for smoothing and for file output, but not if
you just want a total summary at the end of execution (i.e. from
getSummary). This must not be called within a timing block.
*/
inline void endCycle();
/**
Returns the average time used in the named block per profiling cycle.
If smoothing is disabled (see init), this returns the most recent
duration measurement.
@param name The name of the block.
@param format The desired time format to use for the result.
@return The block's average duration per cycle.
*/
inline double getAvgDuration(const std::string& name,
TimeFormat format)const;
/**
Returns the total time spent in the named block since the profiler was
initialized.
@param name The name of the block.
@param format The desired time format to use for the result.
@return The block total time.
*/
inline double getTotalDuration(const std::string& name,
TimeFormat format);
/**
Computes the elapsed time since the profiler was initialized.
@param format The desired time format to use for the result.
@return The elapsed time.
*/
inline double getTimeSinceInit(TimeFormat format);
/**
Returns a summary of total times in each block.
@param format The desired time format to use for the results.
@return The timing summary as a string.
*/
inline std::string getSummary(TimeFormat format=PERCENT);
inline std::string getAvgSummary(TimeFormat format=PERCENT);
private:
/**
Returns everything to its initial state.
Deallocates memory, closes output files, and resets all variables.
This is called when the profiler is re-initialized and when the
process exits.
*/
inline void destroy();
/**
Prints an error message to standard output.
@param msg The string to print.
*/
inline void printError(const std::string& msg)const;
/**
Returns a named profile block.
@param name The name of the block to return.
@return The named ProfileBlock, or NULL if it can't be found.
*/
inline ProfileBlock* getProfileBlock(const std::string& name)const;
/**
Returns the appropriate suffix string for the given time format.
@return The suffix string.
*/
inline std::string getSuffixString(TimeFormat format)const;
/// Determines whether the profiler is enabled.
bool mEnabled;
/// The clock used to time profile blocks.
Clock mClock;
/// The starting time (in us) of the current profiling cycle.
unsigned long long int mCurrentCycleStartMicroseconds;
/// The average profiling cycle duration (in us). If smoothing is
/// disabled, this is the same as the duration of the most recent
/// cycle.
double mAvgCycleDurationMicroseconds;
/// Internal map of named profile blocks.
std::map<std::string, ProfileBlock*> mProfileBlocks;
/// The data output file used if this feature is enabled in init.
std::ofstream mOutputFile;
/// Tracks whether we have begun printing data to the output file.
bool mFirstFileOutput;
/// A pre-computed scalar used to update exponentially-weighted moving
/// averages.
double mMovingAvgScalar;
/// Determines how often (in number of profiling cycles) timing data
/// is printed to the output file.
size_t mPrintPeriod;
/// The time format used when printing timing data to the output file.
TimeFormat mPrintFormat;
/// Keeps track of how many cycles have elapsed (for printing).
size_t mCycleCounter;
/// Used to update the initial average cycle times.
bool mFirstCycle;
};
Profiler::Profiler()
{
mEnabled = false;
mCurrentCycleStartMicroseconds = 0;
mAvgCycleDurationMicroseconds = 0;
mFirstFileOutput = true;
mMovingAvgScalar = 0;
mPrintPeriod = 1;
mPrintFormat = SECONDS;
mCycleCounter = 0;
mFirstCycle = true;
}
Profiler::~Profiler()
{
// This is called when the program exits because the singleton
// instance is static.
destroy();
}
Profiler& Profiler::instance()
{
static Profiler self;
return self;
}
void Profiler::destroy()
{
mEnabled = false;
mClock.reset();
mCurrentCycleStartMicroseconds = 0;
mAvgCycleDurationMicroseconds = 0;
while (!mProfileBlocks.empty())
{
delete (*mProfileBlocks.begin()).second;
mProfileBlocks.erase(mProfileBlocks.begin());
}
if (mOutputFile.is_open())
{
mOutputFile.close();
}
mFirstFileOutput = true;
mMovingAvgScalar = 0;
mPrintPeriod = 1;
mPrintFormat = SECONDS;
mCycleCounter = 0;
mFirstCycle = true;
}
void Profiler::init(double smoothing, const std::string outputFilename,
size_t printPeriod, TimeFormat printFormat)
{
if (mEnabled)
{
// Reset everything to its initial state and re-initialize.
destroy();
std::cout << "[QuickProf] Re-initializing profiler, "
<< "erasing all profiling blocks" << std::endl;
}
mEnabled = true;
if (smoothing <= 0)
{
if (smoothing < 0)
{
printError("Smoothing parameter must be >= 0. Using 0.");
}
mMovingAvgScalar = 0;
}
else
{
// Treat smoothing as a time constant.
mMovingAvgScalar = ::exp(-1 / smoothing);
}
if (!outputFilename.empty())
{
mOutputFile.open(outputFilename.c_str());
}
if (printPeriod < 1)
{
printError("Print period must be >= 1. Using 1.");
mPrintPeriod = 1;
}
else
{
mPrintPeriod = printPeriod;
}
mPrintFormat = printFormat;
mClock.reset();
// Set the start time for the first cycle.
mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds();
}
void Profiler::beginBlock(const std::string& name)
{
if (!mEnabled)
{
return;
}
if (name.empty())
{
printError("Cannot allow unnamed profile blocks.");
return;
}
ProfileBlock* block = NULL;
std::map<std::string, ProfileBlock*>::iterator iter =
mProfileBlocks.find(name);
if (mProfileBlocks.end() == iter)
{
// The named block does not exist. Create a new ProfileBlock.
block = new ProfileBlock();
mProfileBlocks[name] = block;
}
else
{
block = iter->second;
}
// 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 long int endTick = mClock.getTimeMicroseconds();
ProfileBlock* block = getProfileBlock(name);
if (!block)
{
return;
}
unsigned long long int blockDuration = endTick -
block->currentBlockStartMicroseconds;
block->currentCycleTotalMicroseconds += blockDuration;
block->totalMicroseconds += blockDuration;
}
void Profiler::endCycle()
{
if (!mEnabled)
{
return;
}
// Update the average total cycle time.
// On the first cycle we set the average cycle time equal to the
// measured cycle time. This avoids having to ramp up the average
// from zero initially.
unsigned long long int currentCycleDurationMicroseconds =
mClock.getTimeMicroseconds() - mCurrentCycleStartMicroseconds;
if (mFirstCycle)
{
mAvgCycleDurationMicroseconds =
(double)currentCycleDurationMicroseconds;
}
else
{
mAvgCycleDurationMicroseconds = mMovingAvgScalar *
mAvgCycleDurationMicroseconds + (1 - mMovingAvgScalar)
* (double)currentCycleDurationMicroseconds;
}
// Update the average cycle time for each block.
std::map<std::string, ProfileBlock*>::iterator blocksBegin =
mProfileBlocks.begin();
std::map<std::string, ProfileBlock*>::iterator blocksEnd =
mProfileBlocks.end();
std::map<std::string, ProfileBlock*>::iterator iter = blocksBegin;
for (; iter != blocksEnd; ++iter)
{
ProfileBlock* block = iter->second;
// On the first cycle we set the average cycle time equal to the
// measured cycle time. This avoids having to ramp up the average
// from zero initially.
if (mFirstCycle)
{
block->avgCycleTotalMicroseconds =
(double)block->currentCycleTotalMicroseconds;
}
else
{
block->avgCycleTotalMicroseconds = mMovingAvgScalar *
block->avgCycleTotalMicroseconds + (1 - mMovingAvgScalar) *
(double)block->currentCycleTotalMicroseconds;
}
block->currentCycleTotalMicroseconds = 0;
}
if (mFirstCycle)
{
mFirstCycle = false;
}
// If enough cycles have passed, print data to the output file.
if (mOutputFile.is_open() && mCycleCounter % mPrintPeriod == 0)
{
mCycleCounter = 0;
if (mFirstFileOutput)
{
// On the first iteration, print a header line that shows the
// names of each data column (i.e. profiling block names).
mOutputFile << "# t(s)";
std::string suffix = getSuffixString(mPrintFormat);
for (iter = blocksBegin; iter != blocksEnd; ++iter)
{
mOutputFile << " " << (*iter).first << "(" << suffix << ")";
}
mOutputFile << std::endl;
mFirstFileOutput = false;
}
mOutputFile << getTimeSinceInit(SECONDS) * (double)0.000001;
// Print the cycle time for each block.
for (iter = blocksBegin; iter != blocksEnd; ++iter)
{
mOutputFile << " " << getAvgDuration((*iter).first,
mPrintFormat);
}
mOutputFile << std::endl;
}
++mCycleCounter;
mCurrentCycleStartMicroseconds = mClock.getTimeMicroseconds();
}
double Profiler::getAvgDuration(const std::string& name,
TimeFormat format)const
{
if (!mEnabled)
{
return 0;
}
ProfileBlock* block = getProfileBlock(name);
if (!block)
{
return 0;
}
double result = 0;
switch(format)
{
case SECONDS:
result = block->avgCycleTotalMicroseconds * (double)0.000001;
break;
case MILLISECONDS:
result = block->avgCycleTotalMicroseconds * (double)0.001;
break;
case MICROSECONDS:
result = block->avgCycleTotalMicroseconds;
break;
case PERCENT:
{
if (0 == mAvgCycleDurationMicroseconds)
{
result = 0;
}
else
{
result = 100.0 * block->avgCycleTotalMicroseconds /
mAvgCycleDurationMicroseconds;
}
break;
}
default:
break;
}
return result;
}
double Profiler::getTotalDuration(const std::string& name,
TimeFormat format)
{
if (!mEnabled)
{
return 0;
}
ProfileBlock* block = getProfileBlock(name);
if (!block)
{
return 0;
}
double blockTotalMicroseconds = (double)block->totalMicroseconds;
double result = 0;
switch(format)
{
case SECONDS:
result = blockTotalMicroseconds * (double)0.000001;
break;
case MILLISECONDS:
result = blockTotalMicroseconds * (double)0.001;
break;
case MICROSECONDS:
result = blockTotalMicroseconds;
break;
case PERCENT:
{
double microsecondsSinceInit = getTimeSinceInit(MICROSECONDS);
if (0 == microsecondsSinceInit)
{
result = 0;
}
else
{
result = 100.0 * blockTotalMicroseconds /
microsecondsSinceInit;
}
}
break;
default:
break;
}
return result;
}
double Profiler::getTimeSinceInit(TimeFormat format)
{
double timeSinceInit = 0;
switch(format)
{
case SECONDS:
timeSinceInit = (double)mClock.getTimeMicroseconds() * (double)0.000001;
break;
case MILLISECONDS:
timeSinceInit = (double)mClock.getTimeMicroseconds() * (double)0.001;
break;
case MICROSECONDS:
timeSinceInit = (double)mClock.getTimeMicroseconds();
break;
case PERCENT:
{
timeSinceInit = 100;
break;
}
default:
break;
}
if (timeSinceInit < 0)
{
timeSinceInit = 0;
}
return timeSinceInit;
}
std::string Profiler::getSummary(TimeFormat format)
{
if (!mEnabled)
{
return "";
}
std::ostringstream oss;
std::string suffix = getSuffixString(format);
std::map<std::string, ProfileBlock*>::iterator blocksBegin =
mProfileBlocks.begin();
std::map<std::string, ProfileBlock*>::iterator blocksEnd =
mProfileBlocks.end();
std::map<std::string, ProfileBlock*>::iterator iter = blocksBegin;
for (; iter != blocksEnd; ++iter)
{
if (iter != blocksBegin)
{
oss << "\n";
}
oss << iter->first;
oss << ": ";
oss << getTotalDuration(iter->first, format);
oss << " ";
oss << suffix;
}
return oss.str();
}
std::string Profiler::getAvgSummary(TimeFormat format)
{
if (!mEnabled)
{
return "";
}
std::ostringstream oss;
std::string suffix = getSuffixString(format);
std::map<std::string, ProfileBlock*>::iterator blocksBegin =
mProfileBlocks.begin();
std::map<std::string, ProfileBlock*>::iterator blocksEnd =
mProfileBlocks.end();
std::map<std::string, ProfileBlock*>::iterator iter = blocksBegin;
for (; iter != blocksEnd; ++iter)
{
if (iter != blocksBegin)
{
oss << "\n";
}
oss << iter->first;
oss << ": ";
oss << getAvgDuration(iter->first, format);
oss << " ";
oss << suffix;
}
return oss.str();
}
void Profiler::printError(const std::string& msg)const
{
std::cout << "[QuickProf error] " << msg << std::endl;
}
ProfileBlock* Profiler::getProfileBlock(const std::string& name)const
{
std::map<std::string, ProfileBlock*>::const_iterator iter =
mProfileBlocks.find(name);
if (mProfileBlocks.end() == iter)
{
// The named block does not exist. Print an error.
printError("The profile block named '" + name +
"' does not exist.");
return NULL;
}
else
{
return iter->second;
}
}
std::string Profiler::getSuffixString(TimeFormat format)const
{
std::string suffix;
switch(format)
{
case SECONDS:
suffix = "s";
break;
case MILLISECONDS:
suffix = "ms";
break;
case MICROSECONDS:
suffix = "us";
break;
case PERCENT:
{
suffix = "%";
break;
}
default:
break;
}
return suffix;
}
}
#endif
Jump to Line
Something went wrong with that request. Please try again.