Quick and dirty way to profile your code

Question

What method do you use when you want to get performance data about specific code paths?

You don't need classes, tools, or anything else. [Check this out](http://www.wikihow.com/Optimize-Your-Program%27s-Performance) — Mike Dunlavey, Nov 04 '08 at 22:51

score 11 · Accepted Answer · edited Nov 03 '12 at 15:50

This method has several limitations, but I still find it very useful. I'll list the limitations (I know of) up front and let whoever wants to use it do so at their own risk.

The original version I posted over-reported time spent in recursive calls (as pointed out in the comments to the answer).
It's not thread safe, it wasn't thread safe before I added the code to ignore recursion and it's even less thread safe now.
Although it's very efficient if it's called many times (millions), it will have a measurable effect on the outcome so that scopes you measure will take longer than those you don't.

I use this class when the problem at hand doesn't justify profiling all my code or I get some data from a profiler that I want to verify. Basically it sums up the time you spent in a specific block and at the end of the program outputs it to the debug stream (viewable with DbgView), including how many times the code was executed (and the average time spent of course)).

#pragma once
#include <tchar.h>
#include <windows.h>
#include <sstream>
#include <boost/noncopyable.hpp>

namespace scope_timer {
    class time_collector : boost::noncopyable {
        __int64 total;
        LARGE_INTEGER start;
        size_t times;
        const TCHAR* name;

        double cpu_frequency()
        { // cache the CPU frequency, which doesn't change.
            static double ret = 0; // store as double so devision later on is floating point and not truncating
            if (ret == 0) {
                LARGE_INTEGER freq;
                QueryPerformanceFrequency(&freq);
                ret = static_cast<double>(freq.QuadPart);
            }
            return ret;
        }
        bool in_use;

    public:
        time_collector(const TCHAR* n)
            : times(0)
            , name(n)
            , total(0)
            , start(LARGE_INTEGER())
            , in_use(false)
        {
        }

        ~time_collector()
        {
            std::basic_ostringstream<TCHAR> msg;
            msg << _T("scope_timer> ") <<  name << _T(" called: ");

            double seconds = total / cpu_frequency();
            double average = seconds / times;

            msg << times << _T(" times total time: ") << seconds << _T(" seconds  ")
                << _T(" (avg ") << average <<_T(")\n");
            OutputDebugString(msg.str().c_str());
        }

        void add_time(__int64 ticks)
        {
            total += ticks;
            ++times;
            in_use = false;
        }

        bool aquire()
        {
            if (in_use)
                return false;
            in_use = true;
            return true;
        }
    };

    class one_time : boost::noncopyable {
        LARGE_INTEGER start;
        time_collector* collector;
    public:
        one_time(time_collector& tc)
        {
            if (tc.aquire()) {
                collector = &tc;
                QueryPerformanceCounter(&start);
            }
            else
                collector = 0;
        }

        ~one_time()
        {
            if (collector) {
                LARGE_INTEGER end;
                QueryPerformanceCounter(&end);
                collector->add_time(end.QuadPart - start.QuadPart);
            }
        }
    };
}

// Usage TIME_THIS_SCOPE(XX); where XX is a C variable name (can begin with a number)
#define TIME_THIS_SCOPE(name) \
    static scope_timer::time_collector st_time_collector_##name(_T(#name)); \
    scope_timer::one_time st_one_time_##name(st_time_collector_##name)

Here's a method with an off-the-charts effectiveness-to-disbelief quotient: http://stackoverflow.com/questions/266373/one-could-use-a-profiler-but-why-not-just-halt-the-program — Mike Dunlavey, Nov 23 '08 at 00:19
looks like there might be div by zero if add_time() is not called — Andrey, May 18 '09 at 19:29
The only way that add_time is not called is if one_time is never destroyed, i.e. one_time is never constructed, And since one_time is created if and only if time_collector is created then there can be no case in which time_collector is destroyed before an instance of one_time is destroyed (due to order of construction). — Motti, May 19 '09 at 09:58
It's assumed that time_collector is only created with a one_time to feed it (as is done via the macros). — Motti, May 26 '09 at 19:45
@Motti: For instrumenting recursive code, you need to measure only the outermost invocations. — Mike Dunlavey, Jul 09 '09 at 20:57
@Mike, that's true and when C++0x's `thread_local` storage specifier will be available I'll update the code to take this into account. — Motti, Jul 11 '09 at 19:15
@Motti: Some people think recursion messes up measurement. But the total time a routine is active is what you would save if it took no time. To see how long it is active, you only need to measure its outermost invocations. Personally I prefer to apply this thinking to statements rather than functions, because statements are the things you can actually fix. — Mike Dunlavey, Jul 14 '09 at 01:07
FYI: I had to remove the tchar macros to get this running with Qt but it is working. — dwj, Aug 19 '09 at 15:51
Isn't this Windows specific? If it is, perhaps it should be mentioned in the answer? — Peter Mortensen, Aug 24 '12 at 18:34
@PeterMortensen the implementation is windows specific but it's easy to convert this to other OSs. — Motti, Aug 26 '12 at 06:24

score 2 · Answer 2 · edited Aug 24 '12 at 19:05

Note, the following is all written specifically for Windows.

I also have a timer class that I wrote to do quick-and-dirty profiling that uses QueryPerformanceCounter() to get high-precision timings, but with a slight difference. My timer class doesn't dump the elapsed time when the Timer object falls out of scope. Instead, it accumulates the elapsed times in to an collection. I added a static member function, Dump(), which creates a table of elapsed times, sorted by timing category (specified in Timer's constructor as a string) along with some statistical analysis such as mean elapsed time, standard deviation, max and min. I also added a Clear() static member function which clears the collection & lets you start over again.

How to use the Timer class (psudocode):

int CInsertBuffer::Read(char* pBuf)
{
       // TIMER NOTES: Avg Execution Time = ~1 ms
       Timer timer("BufferRead");
       :      :
       return -1;
}

Sample output :

Timer Precision = 418.0095 ps

=== Item               Trials    Ttl Time  Avg Time  Mean Time StdDev    ===
    AddTrade           500       7 ms      14 us     12 us     24 us
    BufferRead         511       1:19.25   0.16 s    621 ns    2.48 s
    BufferWrite        516       511 us    991 ns    482 ns    11 us
    ImportPos Loop     1002      18.62 s   19 ms     77 us     0.51 s
    ImportPosition     2         18.75 s   9.38 s    16.17 s   13.59 s
    Insert             515       4.26 s    8 ms      5 ms      27 ms
    recv               101       18.54 s   0.18 s    2603 ns   1.63 s

file Timer.inl :

#include <map>
#include "x:\utils\stlext\stringext.h"
#include <iterator>
#include <set>
#include <vector>
#include <numeric>
#include "x:\utils\stlext\algorithmext.h"
#include <math.h>

    class Timer
    {
    public:
        Timer(const char* name)
        {
            label = std::safe_string(name);
            QueryPerformanceCounter(&startTime);
        }

        virtual ~Timer()
        {
            QueryPerformanceCounter(&stopTime);
            __int64 clocks = stopTime.QuadPart-startTime.QuadPart;
            double elapsed = (double)clocks/(double)TimerFreq();
            TimeMap().insert(std::make_pair(label,elapsed));
        };

        static std::string Dump(bool ClipboardAlso=true)
        {
            static const std::string loc = "Timer::Dump";

            if( TimeMap().empty() )
            {
                return "No trials\r\n";
            }

            std::string ret = std::formatstr("\r\n\r\nTimer Precision = %s\r\n\r\n", format_elapsed(1.0/(double)TimerFreq()).c_str());

            // get a list of keys
            typedef std::set<std::string> keyset;
            keyset keys;
            std::transform(TimeMap().begin(), TimeMap().end(), std::inserter(keys, keys.begin()), extract_key());

            size_t maxrows = 0;

            typedef std::vector<std::string> strings;
            strings lines;

            static const size_t tabWidth = 9;

            std::string head = std::formatstr("=== %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s ===", tabWidth*2, tabWidth*2, "Item", tabWidth, tabWidth, "Trials", tabWidth, tabWidth, "Ttl Time", tabWidth, tabWidth, "Avg Time", tabWidth, tabWidth, "Mean Time", tabWidth, tabWidth, "StdDev");
            ret += std::formatstr("\r\n%s\r\n", head.c_str());
            if( ClipboardAlso ) 
                lines.push_back("Item\tTrials\tTtl Time\tAvg Time\tMean Time\tStdDev\r\n");
            // dump the values for each key
            {for( keyset::iterator key = keys.begin(); keys.end() != key; ++key )
            {
                time_type ttl = 0;
                ttl = std::accumulate(TimeMap().begin(), TimeMap().end(), ttl, accum_key(*key));
                size_t num = std::count_if( TimeMap().begin(), TimeMap().end(), match_key(*key));
                if( num > maxrows ) 
                    maxrows = num;
                time_type avg = ttl / num;

                // compute mean
                std::vector<time_type> sortedTimes;
                std::transform_if(TimeMap().begin(), TimeMap().end(), std::inserter(sortedTimes, sortedTimes.begin()), extract_val(), match_key(*key));
                std::sort(sortedTimes.begin(), sortedTimes.end());
                size_t mid = (size_t)floor((double)num/2.0);
                double mean = ( num > 1 && (num % 2) != 0 ) ? (sortedTimes[mid]+sortedTimes[mid+1])/2.0 : sortedTimes[mid];
                // compute variance
                double sum = 0.0;
                if( num > 1 )
                {
                    for( std::vector<time_type>::iterator timeIt = sortedTimes.begin(); sortedTimes.end() != timeIt; ++timeIt )
                        sum += pow(*timeIt-mean,2.0);
                }
                // compute std dev
                double stddev = num > 1 ? sqrt(sum/((double)num-1.0)) : 0.0;

                ret += std::formatstr("    %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s %-*.*s\r\n", tabWidth*2, tabWidth*2, key->c_str(), tabWidth, tabWidth, std::formatstr("%d",num).c_str(), tabWidth, tabWidth, format_elapsed(ttl).c_str(), tabWidth, tabWidth, format_elapsed(avg).c_str(), tabWidth, tabWidth, format_elapsed(mean).c_str(), tabWidth, tabWidth, format_elapsed(stddev).c_str()); 
                if( ClipboardAlso )
                    lines.push_back(std::formatstr("%s\t%s\t%s\t%s\t%s\t%s\r\n", key->c_str(), std::formatstr("%d",num).c_str(), format_elapsed(ttl).c_str(), format_elapsed(avg).c_str(), format_elapsed(mean).c_str(), format_elapsed(stddev).c_str())); 

            }
            }
            ret += std::formatstr("%s\r\n", std::string(head.length(),'=').c_str());

            if( ClipboardAlso )
            {
                // dump header row of data block
                lines.push_back("");
                {
                    std::string s;
                    for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
                    {
                        if( key != keys.begin() )
                            s.append("\t");
                        s.append(*key);
                    }
                    s.append("\r\n");
                    lines.push_back(s);
                }

                // blow out the flat map of time values to a seperate vector of times for each key
                typedef std::map<std::string, std::vector<time_type> > nodematrix;
                nodematrix nodes;
                for( Times::iterator time = TimeMap().begin(); time != TimeMap().end(); ++time )
                    nodes[time->first].push_back(time->second);

                // dump each data point
                for( size_t row = 0; row < maxrows; ++row )
                {
                    std::string rowDump;
                    for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
                    {
                        if( key != keys.begin() )
                            rowDump.append("\t");
                        if( nodes[*key].size() > row )
                            rowDump.append(std::formatstr("%f", nodes[*key][row]));
                    }
                    rowDump.append("\r\n");
                    lines.push_back(rowDump);
                }

                // dump to the clipboard
                std::string dump;
                for( strings::iterator s = lines.begin(); s != lines.end(); ++s )
                {
                    dump.append(*s);
                }

                OpenClipboard(0);
                EmptyClipboard();
                HGLOBAL hg = GlobalAlloc(GMEM_MOVEABLE, dump.length()+1);
                if( hg != 0 )
                {
                    char* buf = (char*)GlobalLock(hg);
                    if( buf != 0 )
                    {
                        std::copy(dump.begin(), dump.end(), buf);
                        buf[dump.length()] = 0;
                        GlobalUnlock(hg);
                        SetClipboardData(CF_TEXT, hg);
                    }
                }
                CloseClipboard();
            }

            return ret;
        }

        static void Reset()
        {
            TimeMap().clear();
        }

        static std::string format_elapsed(double d) 
        {
            if( d < 0.00000001 )
            {
                // show in ps with 4 digits
                return std::formatstr("%0.4f ps", d * 1000000000000.0);
            }
            if( d < 0.00001 )
            {
                // show in ns
                return std::formatstr("%0.0f ns", d * 1000000000.0);
            }
            if( d < 0.001 )
            {
                // show in us
                return std::formatstr("%0.0f us", d * 1000000.0);
            }
            if( d < 0.1 )
            {
                // show in ms
                return std::formatstr("%0.0f ms", d * 1000.0);
            }
            if( d <= 60.0 )
            {
                // show in seconds
                return std::formatstr("%0.2f s", d);
            }
            if( d < 3600.0 )
            {
                // show in min:sec
                return std::formatstr("%01.0f:%02.2f", floor(d/60.0), fmod(d,60.0));
            }
            // show in h:min:sec
            return std::formatstr("%01.0f:%02.0f:%02.2f", floor(d/3600.0), floor(fmod(d,3600.0)/60.0), fmod(d,60.0));
        }

    private:
        static __int64 TimerFreq()
        {
            static __int64 freq = 0;
            static bool init = false;
            if( !init )
            {
                LARGE_INTEGER li;
                QueryPerformanceFrequency(&li);
                freq = li.QuadPart;
                init = true;
            }
            return freq;
        }
        LARGE_INTEGER startTime, stopTime;
        std::string label;

        typedef std::string key_type;
        typedef double time_type;
        typedef std::multimap<key_type, time_type> Times;
//      static Times times;
        static Times& TimeMap()
        {
            static Times times_;
            return times_;
        }

        struct extract_key : public std::unary_function<Times::value_type, key_type>
        {
            std::string operator()(Times::value_type const & r) const
            {
                return r.first;
            }
        };

        struct extract_val : public std::unary_function<Times::value_type, time_type>
        {
            time_type operator()(Times::value_type const & r) const
            {
                return r.second;
            }
        };
        struct match_key : public std::unary_function<Times::value_type, bool>
        {
            match_key(key_type const & key_) : key(key_) {};
            bool operator()(Times::value_type const & rhs) const
            {
                return key == rhs.first;
            }
        private:
            match_key& operator=(match_key&) { return * this; }
            const key_type key;
        };

        struct accum_key : public std::binary_function<time_type, Times::value_type, time_type>
        {
            accum_key(key_type const & key_) : key(key_), n(0) {};
            time_type operator()(time_type const & v, Times::value_type const & rhs) const
            {
                if( key == rhs.first )
                {
                    ++n;
                    return rhs.second + v;
                }
                return v;
            }
        private:
            accum_key& operator=(accum_key&) { return * this; }
            const Times::key_type key;
            mutable size_t n;
        };
    };

file stringext.h (provides formatstr() function):

namespace std
{
    /*  ---

    Formatted Print

        template<class C>
        int strprintf(basic_string<C>* pString, const C* pFmt, ...);

        template<class C>
        int vstrprintf(basic_string<C>* pString, const C* pFmt, va_list args);

    Returns :

        # characters printed to output


    Effects :

        Writes formatted data to a string.  strprintf() works exactly the same as sprintf(); see your
        documentation for sprintf() for details of peration.  vstrprintf() also works the same as sprintf(), 
        but instead of accepting a variable paramater list it accepts a va_list argument.

    Requires :

        pString is a pointer to a basic_string<>

    --- */

    template<class char_type> int vprintf_generic(char_type* buffer, size_t bufferSize, const char_type* format, va_list argptr);

    template<> inline int vprintf_generic<char>(char* buffer, size_t bufferSize, const char* format, va_list argptr)
    {
#       ifdef SECURE_VSPRINTF
        return _vsnprintf_s(buffer, bufferSize-1, _TRUNCATE, format, argptr);
#       else
        return _vsnprintf(buffer, bufferSize-1, format, argptr);
#       endif
    }

    template<> inline int vprintf_generic<wchar_t>(wchar_t* buffer, size_t bufferSize, const wchar_t* format, va_list argptr)
    {
#       ifdef SECURE_VSPRINTF
        return _vsnwprintf_s(buffer, bufferSize-1, _TRUNCATE, format, argptr);
#       else
        return _vsnwprintf(buffer, bufferSize-1, format, argptr);
#       endif
    }

    template<class Type, class Traits>
    inline int vstringprintf(basic_string<Type,Traits> & outStr, const Type* format, va_list args)
    {
        // prologue
        static const size_t ChunkSize = 1024;
        size_t curBufSize = 0;
        outStr.erase(); 

        if( !format )
        {
            return 0;
        }

        // keep trying to write the string to an ever-increasing buffer until
        // either we get the string written or we run out of memory
        while( bool cont = true )
        {
            // allocate a local buffer
            curBufSize += ChunkSize;
            std::ref_ptr<Type> localBuffer = new Type[curBufSize];
            if( localBuffer.get() == 0 )
            {
                // we ran out of memory -- nice goin'!
                return -1;
            }
            // format output to local buffer
            int i = vprintf_generic(localBuffer.get(), curBufSize * sizeof(Type), format, args);
            if( -1 == i )
            {
                // the buffer wasn't big enough -- try again
                continue;
            }
            else if( i < 0 )
            {
                // something wierd happened -- bail
                return i;
            }
            // if we get to this point the string was written completely -- stop looping
            outStr.assign(localBuffer.get(),i);
            return i;
        }
        // unreachable code
        return -1;
    };

    // provided for backward-compatibility
    template<class Type, class Traits>
    inline int vstrprintf(basic_string<Type,Traits> * outStr, const Type* format, va_list args)
    {
        return vstringprintf(*outStr, format, args);
    }

    template<class Char, class Traits>
    inline int stringprintf(std::basic_string<Char, Traits> & outString, const Char* format, ...)
    {
        va_list args;
        va_start(args, format);
        int retval = vstringprintf(outString, format, args);
        va_end(args);
        return retval;
    }

    // old function provided for backward-compatibility
    template<class Char, class Traits>
    inline int strprintf(std::basic_string<Char, Traits> * outString, const Char* format, ...)
    {
        va_list args;
        va_start(args, format);
        int retval = vstringprintf(*outString, format, args);
        va_end(args);
        return retval;
    }

    /*  ---

    Inline Formatted Print

        string strprintf(const char* Format, ...);

    Returns :

        Formatted string


    Effects :

        Writes formatted data to a string.  formatstr() works the same as sprintf(); see your
        documentation for sprintf() for details of operation.  

    --- */

    template<class Char>
    inline std::basic_string<Char> formatstr(const Char * format, ...)
    {
        std::string outString;

        va_list args;
        va_start(args, format);
        vstringprintf(outString, format, args);
        va_end(args);
        return outString;
    }
};

File algorithmext.h (provides transform_if() function) :

/*  ---

Transform
25.2.3

    template<class InputIterator, class OutputIterator, class UnaryOperation, class Predicate>
        OutputIterator transform_if(InputIterator first, InputIterator last, OutputIterator result, UnaryOperation op, Predicate pred)

    template<class InputIterator1, class InputIterator2, class OutputIterator, class BinaryOperation, class Predicate>
        OutputIterator transform_if(InputIterator first, InputIterator last, OutputIterator result, BinaryOperation binary_op, Predicate pred)

Requires:   

    T is of type EqualityComparable (20.1.1) 
    op and binary_op have no side effects

Effects :

    Assigns through every iterator i in the range [result, result + (last1-first1)) a new corresponding value equal to one of:
        1:  op( *(first1 + (i - result)) 
        2:  binary_op( *(first1 + (i - result), *(first2 + (i - result))

Returns :

    result + (last1 - first1)

Complexity :

    At most last1 - first1 applications of op or binary_op

--- */

template<class InputIterator, class OutputIterator, class UnaryFunction, class Predicate>
OutputIterator transform_if(InputIterator first, 
                            InputIterator last, 
                            OutputIterator result, 
                            UnaryFunction f, 
                            Predicate pred)
{
    for (; first != last; ++first)
    {
        if( pred(*first) )
            *result++ = f(*first);
    }
    return result; 
}

template<class InputIterator1, class InputIterator2, class OutputIterator, class BinaryOperation, class Predicate>
OutputIterator transform_if(InputIterator1 first1, 
                            InputIterator1 last1, 
                            InputIterator2 first2, 
                            OutputIterator result, 
                            BinaryOperation binary_op, 
                            Predicate pred)
{
    for (; first1 != last1 ; ++first1, ++first2)
    {
        if( pred(*first1) )
            *result++ = binary_op(*first1,*first2);
    }
    return result;
}

Straight out of the box, this code produces several errors, notably, there's neither std::safe_string, nor std::ref_ptr (at least, in a standard installation) — B. Decoster, May 12 '11 at 08:41

score 2 · Answer 3 · edited Nov 03 '12 at 15:52

2

Well, I have two code snippets. In pseudocode they are looking like (it's a simplified version, I'm using QueryPerformanceFrequency actually):

First snippet:

Timer timer = new Timer
timer.Start

Second snippet:

timer.Stop
show elapsed time

A bit of hot-keys kung fu, and I can say how much time this piece of code stole from my CPU.

edited Nov 03 '12 at 15:52

Peter Mortensen

30,738
21
105
131

answered Sep 14 '08 at 11:26

aku

122,288
32
173
203

score 2 · Answer 4 · edited Aug 24 '12 at 18:38

I do my profiles by creating two classes: cProfile and cProfileManager.

cProfileManager will hold all the data that resulted from cProfile.

cProfile with have the following requirements:

cProfile has a constructor which initializes the current time.
cProfile has a deconstructor which sends the total time the class was alive to cProfileManager

To use these profile classes, I first make an instance of cProfileManager. Then, I put the code block, which I want to profile, inside curly braces. Inside the curly braces, I create a cProfile instance. When the code block ends, cProfile will send the time it took for the block of code to finish to cProfileManager.

Example Code Here's an example of the code (simplified):

class cProfile
{
    cProfile()
    {
        TimeStart = GetTime();
    };

    ~cProfile()
    {
        ProfileManager->AddProfile (GetTime() - TimeStart);
    }

    float TimeStart;
}

To use cProfile, I would do something like this:

int main()
{
    printf("Start test");
    {
        cProfile Profile;
        Calculate();
    }
    ProfileManager->OutputData();
}

or this:

void foobar()
{
    cProfile ProfileFoobar;

    foo();
    {
        cProfile ProfileBarCheck;
        while (bar())
        {
            cProfile ProfileSpam;
            spam();
        }
    }
}

Technical Note

This code is actually an abuse of the way scoping, constructors and deconstructors work in C++. cProfile exists only inside the block scope (the code block we want to test). Once the program leaves the block scope, cProfile records the result.

Additional Enhancements

You can add a string parameter to the constructor so you can do something like this: cProfile Profile("Profile for complicated calculation");
You can use a macro to make the code look cleaner (be careful not to abuse this. Unlike our other abuses on the language, macros can be dangerous when used).

Example:

#define START_PROFILE cProfile Profile(); { #define END_PROFILE }
cProfileManager can check how many times a block of code is called. But you would need an identifier for the block of code. The first enhancement can help identify the block. This can be useful in cases where the code you want to profile is inside a loop (like the second example aboe). You can also add the average, fastest and longest execution time the code block took.
Don't forget to add a check to skip profiling if you are in debug mode.

Your START_PROFILE macro should start with the open curly brace and not have parens (otherwise it's a function declaration and not a variable "{ cProfile Profile;" Also the ctor and dtor in cProfile should be public. — Motti, Sep 15 '08 at 06:33
Would the compiler optimizations affect measurements? In other words, is there any guarantee that the destructor is called only after leaving the scope? — mhernandez, Nov 05 '18 at 01:05

score 0 · Answer 5 · edited Aug 24 '12 at 18:58

I have a quick-and-dirty profiling class that can be used in profiling in even the most tight inner loops. The emphasis is on extreme light weight and simple code. The class allocates a two-dimensional array of fixed size. I then add "checkpoint" calls all over the place. When checkpoint N is reached immediately after checkpoint M, I add the time elapsed (in microseconds) to the array item [M,N]. Since this is designed to profile tight loops, I also have "start of iteration" call that resets the the "last checkpoint" variable. At the end of test, the dumpResults() call produces the list of all pairs of checkpoints that followed each other, together with total time accounted for and unaccounted for.

score 0 · Answer 6 · answered Jun 12 '17 at 00:29

I wrote a simple cross-platform class called nanotimer for this reason. The goal was to be as lightweight as possible so as to not interfere with actual code performance by adding too many instructions and thereby influencing the instruction cache. It is capable of getting microsecond accuracy across windows, mac and linux (and probably some unix variants).

Basic usage:

plf::timer t;
timer.start();

// stuff

double elapsed = t.get_elapsed_ns(); // Get nanoseconds

start() also restarts the timer when necessary. "Pausing" the timer can be achieved by storing the elapsed time, then restarting the timer when "unpausing" and adding to the stored result the next time you check elapsed time.

score 0 · Answer 7 · edited Aug 21 '12 at 19:06

0

The article Code profiler and optimizations has lots of information about C++ code profiling and also has a free download link to a program/class that will show you a graphic presentation for different code paths/methods.

edited Aug 21 '12 at 19:06

Peter Mortensen

30,738
21
105
131

answered Sep 14 '08 at 11:27

Espo

41,399
21
132
159

score 0 · Answer 8 · answered Jun 15 '23 at 11:15

With C++11 the chrono header provides many useful timing functions. So you can measure a specific section of code and cast it to the appropriate measurement e.g. seconds or milliseconds.

#include <iostream>
#include <chrono>

int main() {
    auto const t0 = std::chrono::steady_clock::now();
    std::cout << "Hello world" << std::endl;
    auto const t1 = std::chrono::steady_clock::now();

    auto const us = std::chrono::duration_cast<std::chrono::microseconds>(t1-t0);
    auto const ms = std::chrono::duration_cast<std::chrono::milliseconds>(t1-t0);
    auto const s = std::chrono::duration_cast<std::chrono::seconds>(t1-t0);

    std::cout << "time taken in s " << s.count() << std::endl;
    std::cout << "time taken in ms " << ms.count() << std::endl;
    std::cout << "time taken in us " << us.count() << std::endl;
}

Output:

Hello world
time taken in s 0
time taken in ms 0
time taken in us 30

Quick and dirty way to profile your code

8 Answers8

First snippet:

Second snippet:

Linked