gettime: fix race/bug with threads and time keeping
authorJens Axboe <axboe@kernel.dk>
Tue, 18 Dec 2012 07:23:44 +0000 (08:23 +0100)
committerJens Axboe <axboe@kernel.dk>
Tue, 18 Dec 2012 07:23:44 +0000 (08:23 +0100)
commit1d69e8acd7d338822bfe9630e7cdceee159c7bd2
treef8883dfac15d6f19e435602b5db58907402d968f
parent23893646c9306b785f866fb9e976f3db673af0ca
gettime: fix race/bug with threads and time keeping

Sam writes:

First, the 1 second latency events come in batches and those batches
occur suspiciously close to a usec wrap (0.999999 us -> 1.000000 us).
Second, if you subtract exactly 1 second from these outlier latencies,
the remaining amount is very close to what our instrumented low level
driver records for the IO latency and consistent with the expected
latencies of our SSD.  Similarly, the tv_usec portion of the timeval
structs shows increasing values.  See snippet below.

Format is like    start: <start_time.tv_sec>.<start_time.tv_usec>

latency: 1004657 us, lba: 1111289192, start: 1355776806.995294 issue: 1355776806.995312 complete: 1355776807.999969
latency: 1000494 us, lba: 203093568, start: 1355776806.999456 issue: 1355776806.999475 complete: 1355776807.999969
latency: 1000404 us, lba: 551350992, start: 1355776806.999546 issue: 1355776806.999565 complete: 1355776807.999969
latency: 1000477 us, lba: 449672928, start: 1355776806.999484 issue: 1355776806.999492 complete: 1355776807.999969

All this pointed to the time collection code being buggy.  Reviewing the
code, I spotted this in fio_gettime():

/*
 * If Linux is using the tsc clock on non-synced processors,
 * sometimes time can appear to drift backwards. Fix that up.
 */
if (last_tv_valid) {
if (tp->tv_sec < last_tv.tv_sec)
tp->tv_sec = last_tv.tv_sec;
else if (last_tv.tv_sec == tp->tv_sec &&
 tp->tv_usec < last_tv.tv_usec)
tp->tv_usec = last_tv.tv_usec;
}
last_tv_valid = 1;
memcpy(&last_tv, tp, sizeof(*tp));

This does not appear to be multi-thread safe.  Pre-emption can occur
between either comparison and the subsequent update.  Commenting it out
makes the problem go away (at the expense of being subject to drift).
How about making last_tv & last_tv_valid thread-local?

Reported-by: Sam Bradshaw <sbradshaw@micron.com>
Signed-off-by: Jens Axboe <axboe@kernel.dk>
gettime.c