General purpose code performance measurement on Windows

Question

Growing more and more concerned about the real-world performance, especially the execution time, of my code (not just from the perspective of Complexity theory) I decided to build a performance metrics library to get some numbers about the execution time of code.

I basically want a function which takes another function with its parameters as argument, executes it and measures the execution time.

getPerformance(function, function_arg1, function_arg2, ...)

Here is the code;

// Compiled with MinGW gcc version 5.1.0 (tdm64-1), tested on Windows 10 Edu 17134

#include <algorithm>
#include <chrono>
#include <iostream>
#include <time.h>
#include <utility>
#include <windows.h>

#define currentTime() std::chrono::high_resolution_clock::now()

//#define ERROR_GENERAL 0x1 
#define ERROR_NULL_POINTER 0x2

typedef std::chrono::high_resolution_clock::time_point ChronoTime; 


// Uses Windows Performance Counters 
template<typename F, typename... Args>
double performanceMethod1(F function, Args&&... args);
long long performanceMethod1Time(); 

// Uses GetSystemTimeAsFileTime
template<typename F, typename... Args>
long long performanceMethod2(F function, Args&&...args); 
unsigned long long getTime(); 
unsigned long long WindowsTickToUnixSeconds(long long windowsTicks); 

// Uses C/C++ std lib time()
template<typename F, typename... Args>
double performanceMethod3(F function, Args&&... args); 

// Uses C++ Chrono 
template<typename F, typename... Args>
double performanceMethod4(F function, Args&&... args);


// Test the performance of these algorithms, more to come 
void testAlgoFibonacci(unsigned int upperBound);
//void testAlgoMarkov(struct *pMarkov, char *pStr);

int main(void) 
{
     std::cout << "Test performance with Fibonacci numbers." << std::endl; 

     std::cout << "\nExecuting Fibonacci algorithm, retrieving time with QueryPerformanceFrequency." << std::endl;  
     std::cout << "Algorithm time:" << performanceMethod1(testAlgoFibonacci, 2000000000) << "ms" << std::endl; 

     std::cout << "\nExecuting Fibonacci algorithm, retrieving time with GetSystemTimeAsFileTime." << std::endl; 
     std::cout << "Algorithm time:" << performanceMethod2(testAlgoFibonacci, 2000000000) << "ms" << std::endl; 

     std::cout << "\nExecuting Fibonacci algorithm, retrieving time with C clock function." << std::endl; 
     std::cout << "Algorithm time:" << performanceMethod3(testAlgoFibonacci, 2000000000) << "ms" << std::endl; 

     std::cout << "\nExecuting Fibonacci algorithm, retrieving time with C++ chrono." << std::endl; 
     std::cout << "Algorithm time:" << performanceMethod4(testAlgoFibonacci, 2000000000) << "s" << std::endl; 
     return 0; 
}


template<typename F, typename... Args>
double performanceMethod1(F function, Args&&... args)
{
    if(function == NULL) 
    {
        std::cout << "NULL pointer reference for 'function' in performanceMethod1" << std::endl; 
        return ERROR_NULL_POINTER;         
    }    
    long long start = performanceMethod1Time(); 
    function(std::forward<Args>(args)...); 
    long long end = performanceMethod1Time(); 
    return (end - start); 
}

long long performanceMethod1Time() 
{
    static LARGE_INTEGER largeIntegerX;
    static BOOL qpf = QueryPerformanceFrequency(&largeIntegerX);

    if (qpf) 
    {
        LARGE_INTEGER largeIntegerY;
        QueryPerformanceCounter(&largeIntegerY);
        return (1000LL * largeIntegerY.QuadPart) / largeIntegerX.QuadPart;
    } 

    return GetTickCount();    
}


template<typename F, typename... Args>
long long performanceMethod2(F function, Args&&...args) 
{
    if(function == NULL) 
    {
        std::cout << "NULL pointer reference for 'function' in performanceMethod2" << std::endl; 
        return ERROR_NULL_POINTER; 
    }
    unsigned long long start = getTime(); 
    function(std::forward<Args>(args)...);
    unsigned long long end = getTime(); 
    return (end - start); 
}

unsigned long long getTime()
{
    FILETIME fileTime;
    LARGE_INTEGER largeIntegerX;
    //There is also GetSystemTimePreciseAsFileTime for UTC sync time stamps   
    //https://msdn.microsoft.com/en-us/library/windows/desktop/hh706895(v=vs.85).aspx 
    GetSystemTimeAsFileTime(&fileTime);
    largeIntegerX.LowPart = fileTime.dwLowDateTime;
    largeIntegerX.HighPart = fileTime.dwHighDateTime;
    unsigned long long ret = largeIntegerX.QuadPart;    
    return WindowsTickToUnixSeconds(ret);
}

unsigned long long WindowsTickToUnixSeconds(long long windowsTicks)
{
    windowsTicks = windowsTicks - 116444736000000000LL;
    windowsTicks = windowsTicks / 10000; 
    return windowsTicks; 
}


template<typename F, typename... Args>
double performanceMethod3(F function, Args&&... args)
{
    if(function == NULL) 
    {
        std::cout << "NULL pointer reference for 'function' in performanceMethod3" << std::endl; 
        return ERROR_NULL_POINTER; 
    }
    clock_t start, end; 
    start = clock(); 
    function(std::forward<Args>(args)...);  
    end = clock(); 
    return (end - start); 
}

template<typename F, typename... Args>
double performanceMethod4(F function, Args&&... args)
{
    if(function == NULL) 
    {
        std::cout << "NULL pointer reference for 'function' in performanceMethod4" << std::endl; 
        return ERROR_NULL_POINTER; 
    }
    ChronoTime timeBeforeFunction = currentTime(); 
    function(std::forward<Args>(args)...); 
    ChronoTime timeAfterFunction = currentTime(); 
    return std::chrono::duration_cast<std::chrono::nanoseconds>(timeAfterFunction - timeBeforeFunction).count();
} 


void testAlgoFibonacci(unsigned int upperBound)
{
    size_t t1, t2, sum;
    t1 = 0; 
    t2 = 1; 
    sum = 0; 

    for (unsigned int i = 1; i <= upperBound; ++i)
    {
        sum = t1 + t2;
        t1 = t2;
        t2 = sum;
    }
    return; 
}

Each performanceMethod function implements a different way to get the Wall time of the function to be tested, in this case the Fibonacci algorithm. All four performance methods simply expect the function with its parameters as arguments.

performanceMethod1(testAlgoFibonacci, 2000000000)

testAlgoFibonacci is the code to be measured, 2000000000 its only parameter.

I compiled the source with TDM MinGW 5.1

g++  -Wall -std=c++11 benchmark.cpp -o benchmark.exe

An example output with a low CPU load around 30% looks like this

Test performance with Fibonacci numbers.

Executing Fibonacci algorithm, retrieving time with QueryPerformanceFrequency.

Algorithm time:6014ms

Executing Fibonacci algorithm, retrieving time with GetSystemTimeAsFileTime.

Algorithm time:6263ms

Executing Fibonacci algorithm, retrieving time with C clock function.

Algorithm time:6619ms

Executing Fibonacci algorithm, retrieving time with C++ chrono.

Algorithm time:6.36697e+009s

Mayor concerns are:

• Variance between measurements when determining the execution time of a multithreaded function.

• Intuitive function names. "performanceMethodX" sounds bad, but "performanceMethodChrono" or "performanceMethodGetSystemTimeAsFileTime" even worse.

• Graphical representation by a chart when measuring the code performance of a function over longer periods of time.

• Logging of hardware specific's, how necessary is it ?

• Should there be a wrapper function e.g.

    getPerformance(method="CHRONO", function, **args) 
  

with a default selection (For example QueryPerformanceFrequency as recommended by Microsoft) for performance metrics ?

Answer 1

Timer Design

I'm not a big fan of most software patterns, but this looks to me like a nearly perfect fit for one that I think really is quite useful--the strategy pattern.

In this case, each performanceMethodN function really does two somewhat unrelated things:

1. Invokes a specified function (or some sort of callable thing, anyway), and
2. Keeps track of the time it took to execute

To the extent possible, we'd like to decouple those responsibilities.

The strategy pattern gives us a fairly clean way to do that. In C++ it's usually implemented using a template, so we could define our performance function something like this:

template <typename Timer = ChronoTimer, typename F, typename ...Args>
Timer performance(F f, Args &&...args)
{
    Timer t;
    t.start();
    auto r = f(std::forward<Args>(args)...);
    t.stop();
    std::cout << "f returned: " << r << "\n";
    return t;
}

I've added a bit of code to print out the value returned by the function under test--this helps prevent the compiler from optimizing out the function call completely, after noticing that it's dead code (i.e., uses the CPU a lot, but doesn't actually produce any result that we use).

I've also given a default for the timer to use, to make life easier in cases where you don't necessarily care all that much about which timer gets used, and just want a reasonable measurement as easily as possible.

This leaves us to implement the individual timers (of which I'll include only two, to save a bit of space):

class ChronoTimer {
    using point = std::chrono::high_resolution_clock::time_point;
    point start_;
    point stop_;
public:   
    void start() { start_ = std::chrono::high_resolution_clock::now(); }
    void stop() { stop_ = std::chrono::high_resolution_clock::now(); }

    friend std::ostream &operator<<(std::ostream &os, ChronoTimer const &t)
    {
        using namespace std::chrono;
        auto diff = duration_cast<microseconds>(t.stop_ - t.start_).count();
        return os << diff << " us";
    }
};

class CTimer {
    clock_t start_;
    clock_t stop_;
public:
    void start() { start_ = clock(); }
    void stop() { stop_ = clock(); }

    friend std::ostream &operator<<(std::ostream &os, CTimer t) {
        auto diff = double(t.stop_ - t.start_) / CLOCKS_PER_SEC * 1000.0;
        return os << diff << " ms";
    }
};

Interfaces and Implementations

With this, we've basically gone back to the standard old adage of separating interface from implementation. We've defined a really simple interface to a timer (we can start it, stop it, and insert it), and allowed multiple implementations of that interface.

Unlike an inheritance-based hierarchy, however, templates let us do this separation with essentially no run-time overhead.

The main thing that's missing is a specification of the interface. That's where C++ Concepts come in--they support directly specifying the interface we're going to use. Unfortunately, they were added quite recently, are still being revised, and not all compilers implement them yet, so I'll forgo actually using them until they've settled down a bit more.

Enhancements

Depending on usage, we might want to add a few more things to that, such as returning the time difference as a double, which would probably be more convenient for drawing a graph (and is pretty trivial to add).

Presentation

When printing out numbers, I'd prefer to present them in more human-readable form, especially when they could get rather large.

int main() {

    auto loc = std::locale("");
    std::cout.imbue(loc);

    unsigned long long max = 2000000000;

    std::cout << "Timing with std::chrono timer\n";
    std::cout << performance(testAlgoFibonacci, max) << "\n";

    std::cout << "Timing with C timer:\n";
    std::cout << performance<CTimer>(testAlgoFibonacci, max) << "\n";
}

The imbue with an empty string for the locale name tells it to choose the locale based on the configuration of the execution environment, so in my case it produces output formatted as an American would normally expect:

Timing with std::chrono timer
f returned: 14,714,669,118,146,848,482
2,926,041 us
Timing with C timer:
f returned: 14,714,669,118,146,848,482
2,915 ms

Most Europeans (among others) typically reverse the sense of , and . in numbers to compared to Americans, so for a European that would typically print out something like this instead:

Timing with std::chrono timer
f returned: 14.714.669.118.146.848.482
2.908.743 us
Timing with C timer:
f returned: 14.714.669.118.146.848.482
2.914 ms