Why are gettimeofday() intervals occasionally negative?

Question

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?

Laryngeal

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. – Polyphony

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. – Polyphony

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). – Telephone

Answer 1

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.

Offcenter

Damn, that is embarrassing. :) – Laryngeal

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! – Polyphony

@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. – Laryngeal

So basically, you need to apply a brain to the error to deeply understand it, but pretty much… it still answers the question. :) – Laryngeal

Answer 2

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.

Lawrenson

I forgot about that stuff! Mac OS doesn't implement the POSIX realtime libraries. You're totally right, though. – Laryngeal

Answer 3

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);

Bailsman

Answer 4

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.

Geraldgeralda

And the insidious thing about ntpd is that it does it in small steps spread out over time, so it's harder to notice. – Clodhopper

Answer 5

do

$ time ./proxy-application

next time

Appellation

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. – Laryngeal