gettime: use nsec in get_cycles_per_msec division
authorVincent Fu <vincent.fu@wdc.com>
Thu, 29 Nov 2018 18:14:18 +0000 (13:14 -0500)
committerJens Axboe <axboe@kernel.dk>
Thu, 29 Nov 2018 18:21:18 +0000 (11:21 -0700)
commita0318e176ace1e53b0049965f63b0c60b55ff8cd
tree44d2e7795df6793f639fbf9d8dad8a50ea8a6d4c
parent3363fa4482e24fb87d8aea3443e11d90f1bfc462
gettime: use nsec in get_cycles_per_msec division

Since we now have ntime_since() we can use nsec in the division for
get_cycles_per_msec(). This makes the cycles_per_msec value that fio
ultimately uses more stable since fio will no longer be using values
truncated to usec.

While we're here also modify some debug prints to make it explicit that
fio ultimately uses a trimmed mean in its time calculations.

On platforms where only gettimeofday() is available this will be no
worse than the original code since we will revert back to using times
truncated to usec.

With the patch, the last three digits of the trimmed mean have a tight
range from 784-786. Without the patch, the corresponding value (labeled
avg) has a much wider range from 821-958. Notice also that the standard
error S is an order of magnitude smaller with the patch.

*** WITH PATCH ***
$ ./fio --debug=time --cpuclock-test | grep mean
time     315   min=3466785, max=3466796, mean=3466789.120000, S=0.057234, N=50
time     315   trimmed mean=3466789, N=29
$ ./fio --debug=time --cpuclock-test | grep mean
time     329   min=3466784, max=3466795, mean=3466789.480000, S=0.053641, N=50
time     329   trimmed mean=3466788, N=36
$ ./fio --debug=time --cpuclock-test | grep mean
time     343   min=3466786, max=3466794, mean=3466789.220000, S=0.036654, N=50
time     343   trimmed mean=3466788, N=42
$ ./fio --debug=time --cpuclock-test | grep mean
time     357   min=3466785, max=3466794, mean=3466789.080000, S=0.053580, N=50
time     357   trimmed mean=3466788, N=33
$ ./fio --debug=time --cpuclock-test | grep mean
time     371   min=3466785, max=3466794, mean=3466789.600000, S=0.043519, N=50
time     371   trimmed mean=3466789, N=36
$ ./fio --debug=time --cpuclock-test | grep mean
time     385   min=3466785, max=3466794, mean=3466789.280000, S=0.052534, N=50
time     385   trimmed mean=3466789, N=32
$ ./fio --debug=time --cpuclock-test | grep mean
time     407   min=3466786, max=3466796, mean=3466789.520000, S=0.042616, N=50
time     407   trimmed mean=3466789, N=41
$ ./fio --debug=time --cpuclock-test | grep mean
time     513   min=3466785, max=3466796, mean=3466789.220000, S=0.051316, N=50
time     513   trimmed mean=3466789, N=35

*** WIHTOUT PATCH ***
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     439   avg: 3466821
time     439   min=3466790, max=3467006, mean=3466838.060000, S=0.959748
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     455   avg: 3466958
time     455   min=3466796, max=3466996, mean=3466945.880000, S=0.789178
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     469   avg: 3466887
time     469   min=3466790, max=3466984, mean=3466887.500000, S=0.825069
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     485   avg: 3466951
time     485   min=3466818, max=3466996, mean=3466939.420000, S=0.873334
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     499   avg: 3466957
time     499   min=3466793, max=3467009, mean=3466950.140000, S=0.764626
$ ./fio-3.11 --debug=time --cpuclock-test | grep 'mean\|avg'
time     608   avg: 3466954
time     608   min=3466818, max=3466981, mean=3466937.040000, S=0.862232

Signed-off-by: Jens Axboe <axboe@kernel.dk>
gettime.c