6

I have an experimental library whose performance I'm trying to measure. To do this, I've written the following:

struct timeval begin;
gettimeofday(&begin, NULL);
{
    // Experiment!
}
struct timeval end;
gettimeofday(&end, NULL);

// Print the time it took!
std::cout << "Time: " << 100000 * (end.tv_sec - begin.tv_sec) + (end.tv_usec - begin.tv_usec) << std::endl;

Occasionally, my results include negative timings, some of which are nonsensical. For instance:

Time: 226762
Time: 220222
Time: 210883
Time: -688976

What's going on?

Andres Jaan Tack
  • 22,566
  • 11
  • 59
  • 78
  • 5
    you get negatives because timeval is a multi component structure. in short made up of second and useconds. if you naively diff the common compoents in the 2nd tv by the 1st tv, you will get negatives. for example consider tv1 as being 1sec 3usec from epoch and tv2 being 4sec and 1usec from epoch. as you can see you now get a negative value in the difference between the usec components. –  Jan 07 '11 at 00:06
  • 1
    You got 4 answers to this question, not one of them even came close to providing a correct answer yet you still selected the most irrelevant one as the final answer. –  Jan 07 '11 at 00:07
  • Interesting addition, but only relevant when using just one of the components, like I was doing (only using the tv_usec components, not the tv_sec ones). – egpbos Jun 20 '13 at 17:59

5 Answers5

6

You've got a typo. Corrected last line (note the number of 0s):

std::cout << "Time: " << 1000000 * (end.tv_sec - begin.tv_sec) + (end.tv_usec - begin.tv_usec) << std::endl;

BTW, timersub is a built in method to get the difference between two timevals.

Michael Ulm
  • 802
  • 1
  • 7
  • 11
  • 1
    Damn, that is embarrassing. :) – Andres Jaan Tack May 06 '10 at 11:38
  • 6
    Why is this considered the answer? its not correct, it just fixes a small bug in the presentation of time. It does not deal with the core problem of why negative times are showing up. READERS NOTE - THIS IS NOT A VALID ANSWER! –  Jan 07 '11 at 00:44
  • @Zenikoder Yes it does. Ordinarily, the absolute value of the minuend (seconds * 1000000) would be larger than the subtrahend, so even if you wrapped over a second you wouldn't get a negative. In this case, the minuend was always too small (missing zero, factor of 10), so the second wraparounds made comparatively large negative numbers in the subtrahend. – Andres Jaan Tack Jan 07 '11 at 08:47
  • 3
    So basically, you need to apply a brain to the error to deeply understand it, but pretty much… it still answers the question. :) – Andres Jaan Tack Jan 07 '11 at 08:48
5

You took care of the negative value but it still isn't correct. The difference between the millisecond variables is erroneous, say we have begin and end times as 1.100s and 2.051s. By the accepted answer this would be an elapsed time of 1.049s which is incorrect.

The below code takes care of the cases where there is only a difference of milliseconds but not seconds and the case where the milliseconds value overflows. 

if(end.tv_sec==begin.tv_sec)
printf("Total Time =%ldus\n",(end.tv_usec-begin.tv_usec));
else
printf("Total Time =%ldus\n",(end.tv_sec-begin.tv_sec-1)*1000000+(1000000-begin.tv_usec)+end.tv_usec);
sdmello
  • 431
  • 2
  • 6
  • 14
5

The posix realtime libraries are better suited for measurement of high accuracy intervals. You really don't want to know the current time. You just want to know how long it has been between two points. That is what the monotonic clock is for.

struct timespec begin;
clock_gettime( CLOCK_MONOTONIC, &begin );
{
    // Experiment!
}
struct timespec end;
clock_gettime(CLOCK_MONOTONIC, &end );

// Print the time it took!
std::cout << "Time: " << double(end.tv_sec - begin.tv_sec) + (end.tv_nsec - begin.tv_nsec)/1000000000.0 << std::endl;

When you link you need to add -lrt.

Using the monotonic clock has several advantages. It often uses the hardware timers (Hz crystal or whatever), so it is often a faster call than gettimeofday(). Also monotonic timers are guaranteed to never go backwards even if ntpd or a user is goofing with the system time.

deft_code
  • 57,255
  • 29
  • 141
  • 224
3

std::cout << "Time: " << 100000 * (end.tv_sec - begin.tv_sec) + (end.tv_usec - begin.tv_usec) << std::endl;

As noted, there are 1000000 usec in a sec, not 100000.

More generally, you may need to be aware of the instability of timing on computers. Processes such as ntpd can change clock times, leading to incorrect delta times. You might be interested in POSIX facilities such as timer_create.

ariels
  • 545
  • 4
  • 17
-1

do

$ time ./proxy-application

next time

Noone
  • 1
  • That doesn't let me time the experiment itself. All of: memory allocator initialization, static object construction, and loading of the program are included. Also, that's only at seconds granularity. – Andres Jaan Tack May 06 '10 at 19:48