Time a function in C++

Question

I'd like to time how long a function takes in C++ in milliseconds.

Here's what I have:

#include<iostream>
#include<chrono>           
using timepoint = std::chrono::steady_clock::time_point;

float elapsed_time[100];

// Run function and count time
for(int k=0;k<100;k++) {

    // Start timer
    const timepoint clock_start = chrono::system_clock::now();

    // Run Function
    Recursive_Foo();

    // Stop timer
    const timepoint clock_stop = chrono::system_clock::now();

    // Calculate time in milliseconds
    chrono::duration<double,std::milli> timetaken = clock_stop - clock_start;
    elapsed_time[k] = timetaken.count();
}

for(int l=0;l<100;l++) {
    cout<<"Array: "<<l<<" Time: "<<elapsed_time[l]<<" ms"<<endl;
}

This compiles but I think multithreading is preventing it from working properly. The output produces times in irregular intervals, e.g.:

Array: 0 Time: 0 ms
Array: 1 Time: 0 ms
Array: 2 Time: 15.6 ms
Array: 3 Time: 0 ms
Array: 4 Time: 0 ms
Array: 5 Time: 0 ms
Array: 6 Time: 15.6 ms
Array: 7 Time: 0 ms
Array: 8 Time: 0 ms

Do I need to use some kind of mutex lock? Or is there an easier way to time how many milliseconds a function took to execute?

EDIT

Maybe people are suggesting using high_resolution_clock or steady_clock, but all three produce the same irregular results.

This solution seems to produce real results: How to use QueryPerformanceCounter? but it's not clear to me why. Also, https://gamedev.stackexchange.com/questions/26759/best-way-to-get-elapsed-time-in-miliseconds-in-windows works well. Seems to be a Windows implementation issue.

Try `steady_clock` or `high_resolution_clock` instead. The granularity of `system_clock` might not be enough. — Rostislav, Oct 25 '15 at 23:11
Yeah, I've tried all 3, same results. I'm assuming it's a multithreading issue although hard to pointpoint. I've also tried passing time_point to the function and when the function ends, returning the difference, but that didn't seem to work either. — OrdinaryHuman, Oct 25 '15 at 23:15
@OrdinaryHuman Maybe thats how your function works? Have you tried measuring sleep? ex. `std::this_thread::sleep_for(std::chrono::milliseconds(15000));` — marcinj, Oct 25 '15 at 23:19
I believe the problem is that you are recording CPU time as opposed to wall time. If you have access to `OpenMP`, you should be able to get the wall time using a function [`omp_get_wtime()`](https://gcc.gnu.org/onlinedocs/libgomp/omp_005fget_005fwtime.html). I'm sure there's an equivalent in whatever multithreading language you're using. In general `system_clock()` will return CPU time - not what you want. — NoseKnowsAll, Oct 26 '15 at 01:50
@NoseKnowsAll Thanks but I don't want the wall time, I need to know how many milliseconds or microseconds a function took to execute. Measuring the wall time along will give me noise -- if there are 15 threads running, for example, then my performance depends on what else is getting CPU time. I'm looking to measure how long a function took to run. I think the `QueryPerformanceCounter` solution via Microsoft below may be the only method on Windows. — OrdinaryHuman, Oct 26 '15 at 01:56
@OrdinaryHuman The number of milliseconds a function takes to execute *is* the wall time. The CPU time is the amount of time taken across all processors. Thus, in a perfectly parallel program, the CPU time will remain the same: i.e. cpu_time=10 seconds on 1 processor will report cpu_time=10 seconds on 10 processors as well. Wall time will be 1 second on 10 processors though, for it is the amount of time the function takes to execute. — NoseKnowsAll, Oct 26 '15 at 02:29

score 3 · Accepted Answer · edited Oct 26 '15 at 11:57

Microsoft has a nice, clean solution in microseconds, via: MSDN

#include <windows.h>

LONGLONG measure_activity_high_resolution_timing()
{
    LARGE_INTEGER StartingTime, EndingTime, ElapsedMicroseconds;
    LARGE_INTEGER Frequency;

    QueryPerformanceFrequency(&Frequency); 
    QueryPerformanceCounter(&StartingTime);

    // Activity to be timed

    QueryPerformanceCounter(&EndingTime);
    ElapsedMicroseconds.QuadPart = EndingTime.QuadPart - StartingTime.QuadPart;


    //
    // We now have the elapsed number of ticks, along with the
    // number of ticks-per-second. We use these values
    // to convert to the number of elapsed microseconds.
    // To guard against loss-of-precision, we convert
    // to microseconds *before* dividing by ticks-per-second.
    //

    ElapsedMicroseconds.QuadPart *= 1000000;
    ElapsedMicroseconds.QuadPart /= Frequency.QuadPart;
    return ElapsedMicroseconds.QuadPart;
}

I have just tested it and it work like a charm. I've done some minor editing to provide the code sample with the required header file: it was not included by default in my VS project (probably because I was reusing a console app project), and MSDN documentation is unclear on this point. — Daniel Strul, Oct 26 '15 at 11:17

score 2 · Answer 2 · answered Oct 25 '15 at 23:14

2

Profile code using a high-resolution timer, not the system-clock; which, as you're seeing, has a very limited granularity.

http://www.cplusplus.com/reference/chrono/high_resolution_clock/

typedef tp high_resolution_clock::time_point

const tp start = high_resolution_clock::now();
// do stuff
const tp end   = high_resolution_clock::now();

answered Oct 25 '15 at 23:14

Dai

141,631
28
261
374

Thanks. I tried it, but high_resolution_clock, system_clock and steady_clock all seem to produce the same irregular results, with most reporting 0s. – OrdinaryHuman Oct 25 '15 at 23:17
@OrdinaryHuman Look at the members of `high_resolution_clock::time_point`, maybe your code ignores higher-resolution values? – Dai Oct 25 '15 at 23:22

score 0 · Answer 3 · answered Oct 25 '15 at 23:15

0

If you suspect that some other process or thread in your app is taking too much CPU time then use:

GetThreadTimes under windows

or

clock_gettime with CLOCK_THREAD_CPUTIME_ID under linux

to measure threads CPU time your function was being executed. This will exclude from your measurements time other threads/processes were executed during profiling.

answered Oct 25 '15 at 23:15

marcinj

48,511
9
79
100

Yes, I think you're onto something. I tried http://stackoverflow.com/questions/1739259/how-to-use-queryperformancecounter and that seems to return real results. – OrdinaryHuman Oct 25 '15 at 23:36

Time a function in C++

EDIT

3 Answers3

Linked