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>

diff --git a/gettime.c b/gettime.c
index f5be6bd00d2eff90a6583eaed217bcc6a498b62e..1a7af377eb24b1aadb31652884ffb312b4235783 100644 (file)
--- a/gettime.c
+++ b/gettime.c
@@ -18,8 +18,8 @@ static unsigned long cycles_per_usec;
 static unsigned long last_cycles;
 int tsc_reliable = 0;
 #endif
 static unsigned long last_cycles;
 int tsc_reliable = 0;
 #endif

-static struct timeval last_tv;
-static int last_tv_valid;
+static __thread struct timeval last_tv;
+static __thread int last_tv_valid;

 
 enum fio_cs fio_clock_source = FIO_PREFERRED_CLOCK_SOURCE;
 int fio_clock_source_set = 0;
 
 enum fio_cs fio_clock_source = FIO_PREFERRED_CLOCK_SOURCE;
 int fio_clock_source_set = 0;