Measuring short time intervals in C on Ubuntu / VMware

Question

I am trying to measure short time intervals, in order few of milliseconds. This proves to be some nontrivial task, since the ubiquitous time() function works on whole seconds precision. After some research I came out with the four methods seen in the code sample below:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>

int main(int argc, char *argv[])
{
    clock_t t0, t1;
    double dt0;

    struct timespec t2, t3;
    double dt1;

    struct timespec t4, t5;
    double dt2;

    struct timeval t6, t7;
    double dt3;

    volatile long long i;

    t2.tv_sec = 0;
    t2.tv_nsec = 0;
    clock_settime(CLOCK_MONOTONIC, &t2);
    clock_settime(CLOCK_REALTIME,  &t2);

    t0 = clock();
    clock_gettime(CLOCK_REALTIME,  &t2);
    clock_gettime(CLOCK_MONOTONIC, &t4);
    gettimeofday(&t6, NULL);

    getchar();
    for (i=0; i<1e9; i++) {};

    gettimeofday(&t7, NULL);
    clock_gettime(CLOCK_MONOTONIC, &t5);
    clock_gettime(CLOCK_REALTIME,  &t3);
    t1 = clock();

    dt0 = (double) (t1 - t0) / CLOCKS_PER_SEC;
    dt1 = (double) (t3.tv_nsec - t2.tv_nsec) / 1e9;
    dt2 = (double) (t5.tv_nsec - t4.tv_nsec) / 1e9;
    dt3 = (double) (t7.tv_usec - t6.tv_usec) / 1e6;

    printf("1. clock():          [0]=%10.0f, [1]=%10.0f, [1-0]=%10.6f sec\n", (double) t0, (double) t1, dt0);
    printf("2. clock_gettime(R): [2]=%10ld, [3]=%10ld, [3-2]=%10f sec\n", (long) t2.tv_nsec, (long) t3.tv_nsec, dt1);
    printf("3. clock_gettime(M): [2]=%10ld, [3]=%10ld, [3-2]=%10f sec\n", (long) t4.tv_nsec, (long) t5.tv_nsec, dt2);
    printf("4. gettimeofday():   [4]=%10ld, [5]=%10ld, [5-4]=%10f sec\n", (long) t6.tv_usec, (long) t7.tv_usec, dt3);

    return 0;
}

Then, I compiled and run it with:

gcc -lrt -o timer.e timer.c; time ./timer.e

I used the getchar() call to introduce a couple of seconds delay to see a difference between real and user time reports, and the result was:

1. clock():          [0]=         0, [1]=   3280000, [1-0]=  3.280000 sec
2. clock_gettime(R): [2]= 823922476, [3]= 478650549, [3-2]= -0.345272 sec
3. clock_gettime(M): [2]= 671137949, [3]= 325864897, [3-2]= -0.345273 sec
4. gettimeofday():   [4]=    823924, [5]=    478648, [5-4]= -0.345276 sec

real    0m6.659s
user    0m3.280s
sys     0m0.010s

As you can see, the only meaningful result is the correlation between method 1 and the user time reported by the time command.

This brings a couple of questions: 1. Why are results 2-4 meaningless? 2. How do I measure the real time spent running a program, like the real number time reports?

My environment is Ubuntu 10.04 LTS 64-bit on VMware on Windows 7 on an AMD based HP laptop.

Answer 1

You're on the right track with clock_gettime().

However, you ought to get rid of those clock_settime() calls: simply call clock_gettime() before and after a block of code, and look at the difference.

Also, when computing the difference, you should take both tv_sec and tv_nsec into account; your current code just looks at the nanosecond component and ignores the full seconds.

On my Ubuntu system the following code gives a pretty accurate measurement of the time it takes to execute the loop:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>

int main(int argc, char *argv[])
{
    struct timespec t2, t3;
    double dt1;

    volatile long long i;

    clock_gettime(CLOCK_MONOTONIC,  &t2);
    for (i=0; i<1e9; i++) {};
    clock_gettime(CLOCK_MONOTONIC,  &t3);
    //time in seconds
    dt1 = (t3.tv_sec - t2.tv_sec) + (double) (t3.tv_nsec - t2.tv_nsec) * 1e-9;
    printf("%f\n", dt1);

    return 0;
}

Answer 2

Some hint about measuring time down to micro and even nano seconds http://en.wikipedia.org/wiki/Time_Stamp_Counter

Answer 3

Your clock_settime calls do not what you think they do. If you'd have the permission they would simply set the system wide clock to 0, probably not what you want. Almost all POSIX functions have a return value that tells you if the call succeeded. Usually it is a bad idea to ignore that value. For your case in particular I think that it should have given this value as it can be found in the man page:

EPERM clock_settime() does not have permission to set the clock indicated.

Luckily you don't have the permissions to set the clock as simply as this :)