Re: gettimeofday() system call timing curiosity

[Jamie Lokier <lk@tantalophile.demon.co.uk>]

H. Peter Anvin wrote:
> > On my laptop, the median of rdtsc+gettimeofday+rdtsc times is 470 cycles
> > for most runs of 1000, but is occasionally 453 cycles.
> 
> What that indicates to me is that 1000 is way too small of a sample. 
> You're only talking a difference of 17,000 cycles, which could -- 
> especially with cache effects -- easily be the time spent in an 
> interrupt handler.

No, interrupt handlers don't (or shouldn't) affect the measurement.

It's the _median_ that varies from 453 to 470, not the _mean_, so the
accumulation to 17000 cycles doesn't apply.

I do rdtsc, then gettimeofday(), then rdtsc.  I record (a) the actual
time values, and (b) the difference between the two rdtsc measurements.

First I store 1000 of the difference measurements -- those are the "time
taken to do measurement in TSC cycles".  I don't want to store a very
large number of these measurements because of the memory it takes, but
perhaps 1000 isn't quite enough (it isn't on the laptop, and is fine on
all the other machines).

Then I sort those and take the 499'th to get the median.

Assuming that at least 50% of the calls don't receive an interrupt or
reschedule in the middle (a reasonable assumption), then that median
gives me a good idea of how long a measurement takes _when there is no
interrupt or reschedule_.

Then I take approx. 1000000 measurements using the same code, and
discard all those that took longer than the median threshold determined
earlier.

This means that whenever an interrupt happened, that sample is discarded.

Finally, I do a simple least-squares linear regression through the
remaining samples (normally 400000-600000 or so) to calculate the slope.

The slope is what's printed.

cheers,
-- Jamie