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?

Answer 1

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.

1. The original version I posted over-reported time spent in recursive calls (as pointed out in the comments to the answer).
2. 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.
3. 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)

Answer 2

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.