gettime: don't attempt to fixup what looks like a backwards clock
[fio.git] / gettime.c
... / ...
CommitLineData
1/*
2 * Clock functions
3 */
4
5#include <unistd.h>
6#include <math.h>
7#include <sys/time.h>
8#include <time.h>
9
10#include "fio.h"
11#include "smalloc.h"
12
13#include "hash.h"
14#include "os/os.h"
15
16#if defined(ARCH_HAVE_CPU_CLOCK) && !defined(ARCH_CPU_CLOCK_CYCLES_PER_USEC)
17static unsigned long cycles_per_usec;
18static unsigned long inv_cycles_per_usec;
19#endif
20int tsc_reliable = 0;
21
22struct tv_valid {
23 uint64_t last_cycles;
24 uint64_t last_tv_valid;
25};
26#ifdef CONFIG_TLS_THREAD
27static __thread struct tv_valid static_tv_valid;
28#else
29static pthread_key_t tv_tls_key;
30#endif
31
32enum fio_cs fio_clock_source = FIO_PREFERRED_CLOCK_SOURCE;
33int fio_clock_source_set = 0;
34static enum fio_cs fio_clock_source_inited = CS_INVAL;
35
36#ifdef FIO_DEBUG_TIME
37
38#define HASH_BITS 8
39#define HASH_SIZE (1 << HASH_BITS)
40
41static struct flist_head hash[HASH_SIZE];
42static int gtod_inited;
43
44struct gtod_log {
45 struct flist_head list;
46 void *caller;
47 unsigned long calls;
48};
49
50static struct gtod_log *find_hash(void *caller)
51{
52 unsigned long h = hash_ptr(caller, HASH_BITS);
53 struct flist_head *entry;
54
55 flist_for_each(entry, &hash[h]) {
56 struct gtod_log *log = flist_entry(entry, struct gtod_log,
57 list);
58
59 if (log->caller == caller)
60 return log;
61 }
62
63 return NULL;
64}
65
66static struct gtod_log *find_log(void *caller)
67{
68 struct gtod_log *log = find_hash(caller);
69
70 if (!log) {
71 unsigned long h;
72
73 log = malloc(sizeof(*log));
74 INIT_FLIST_HEAD(&log->list);
75 log->caller = caller;
76 log->calls = 0;
77
78 h = hash_ptr(caller, HASH_BITS);
79 flist_add_tail(&log->list, &hash[h]);
80 }
81
82 return log;
83}
84
85static void gtod_log_caller(void *caller)
86{
87 if (gtod_inited) {
88 struct gtod_log *log = find_log(caller);
89
90 log->calls++;
91 }
92}
93
94static void fio_exit fio_dump_gtod(void)
95{
96 unsigned long total_calls = 0;
97 int i;
98
99 for (i = 0; i < HASH_SIZE; i++) {
100 struct flist_head *entry;
101 struct gtod_log *log;
102
103 flist_for_each(entry, &hash[i]) {
104 log = flist_entry(entry, struct gtod_log, list);
105
106 printf("function %p, calls %lu\n", log->caller,
107 log->calls);
108 total_calls += log->calls;
109 }
110 }
111
112 printf("Total %lu gettimeofday\n", total_calls);
113}
114
115static void fio_init gtod_init(void)
116{
117 int i;
118
119 for (i = 0; i < HASH_SIZE; i++)
120 INIT_FLIST_HEAD(&hash[i]);
121
122 gtod_inited = 1;
123}
124
125#endif /* FIO_DEBUG_TIME */
126
127#ifdef CONFIG_CLOCK_GETTIME
128static int fill_clock_gettime(struct timespec *ts)
129{
130#ifdef CONFIG_CLOCK_MONOTONIC
131 return clock_gettime(CLOCK_MONOTONIC, ts);
132#else
133 return clock_gettime(CLOCK_REALTIME, ts);
134#endif
135}
136#endif
137
138static void __fio_gettime(struct timeval *tp)
139{
140 struct tv_valid *tv;
141
142#ifdef CONFIG_TLS_THREAD
143 tv = &static_tv_valid;
144#else
145 tv = pthread_getspecific(tv_tls_key);
146#endif
147
148 switch (fio_clock_source) {
149#ifdef CONFIG_GETTIMEOFDAY
150 case CS_GTOD:
151 gettimeofday(tp, NULL);
152 break;
153#endif
154#ifdef CONFIG_CLOCK_GETTIME
155 case CS_CGETTIME: {
156 struct timespec ts;
157
158 if (fill_clock_gettime(&ts) < 0) {
159 log_err("fio: clock_gettime fails\n");
160 assert(0);
161 }
162
163 tp->tv_sec = ts.tv_sec;
164 tp->tv_usec = ts.tv_nsec / 1000;
165 break;
166 }
167#endif
168#ifdef ARCH_HAVE_CPU_CLOCK
169 case CS_CPUCLOCK: {
170 uint64_t usecs, t;
171
172 t = get_cpu_clock();
173 if (t < tv->last_cycles && tv->last_tv_valid)
174 log_err("fio: CPU clock going back in time\n");
175
176 tv->last_cycles = t;
177 tv->last_tv_valid = 1;
178#ifdef ARCH_CPU_CLOCK_CYCLES_PER_USEC
179 usecs = t / ARCH_CPU_CLOCK_CYCLES_PER_USEC;
180#else
181 usecs = (t * inv_cycles_per_usec) / 16777216UL;
182#endif
183 tp->tv_sec = usecs / 1000000;
184 tp->tv_usec = usecs % 1000000;
185 break;
186 }
187#endif
188 default:
189 log_err("fio: invalid clock source %d\n", fio_clock_source);
190 break;
191 }
192}
193
194#ifdef FIO_DEBUG_TIME
195void fio_gettime(struct timeval *tp, void *caller)
196#else
197void fio_gettime(struct timeval *tp, void fio_unused *caller)
198#endif
199{
200#ifdef FIO_DEBUG_TIME
201 if (!caller)
202 caller = __builtin_return_address(0);
203
204 gtod_log_caller(caller);
205#endif
206 if (fio_unlikely(fio_tv)) {
207 memcpy(tp, fio_tv, sizeof(*tp));
208 return;
209 }
210
211 __fio_gettime(tp);
212}
213
214#if defined(ARCH_HAVE_CPU_CLOCK) && !defined(ARCH_CPU_CLOCK_CYCLES_PER_USEC)
215static unsigned long get_cycles_per_usec(void)
216{
217 struct timeval s, e;
218 uint64_t c_s, c_e;
219 enum fio_cs old_cs = fio_clock_source;
220
221#ifdef CONFIG_CLOCK_GETTIME
222 fio_clock_source = CS_CGETTIME;
223#else
224 fio_clock_source = CS_GTOD;
225#endif
226 __fio_gettime(&s);
227
228 c_s = get_cpu_clock();
229 do {
230 uint64_t elapsed;
231
232 __fio_gettime(&e);
233
234 elapsed = utime_since(&s, &e);
235 if (elapsed >= 1280) {
236 c_e = get_cpu_clock();
237 break;
238 }
239 } while (1);
240
241 fio_clock_source = old_cs;
242 return (c_e - c_s + 127) >> 7;
243}
244
245#define NR_TIME_ITERS 50
246
247static int calibrate_cpu_clock(void)
248{
249 double delta, mean, S;
250 uint64_t avg, cycles[NR_TIME_ITERS];
251 int i, samples;
252
253 cycles[0] = get_cycles_per_usec();
254 S = delta = mean = 0.0;
255 for (i = 0; i < NR_TIME_ITERS; i++) {
256 cycles[i] = get_cycles_per_usec();
257 delta = cycles[i] - mean;
258 if (delta) {
259 mean += delta / (i + 1.0);
260 S += delta * (cycles[i] - mean);
261 }
262 }
263
264 /*
265 * The most common platform clock breakage is returning zero
266 * indefinitely. Check for that and return failure.
267 */
268 if (!cycles[0] && !cycles[NR_TIME_ITERS - 1])
269 return 1;
270
271 S = sqrt(S / (NR_TIME_ITERS - 1.0));
272
273 samples = avg = 0;
274 for (i = 0; i < NR_TIME_ITERS; i++) {
275 double this = cycles[i];
276
277 if ((fmax(this, mean) - fmin(this, mean)) > S)
278 continue;
279 samples++;
280 avg += this;
281 }
282
283 S /= (double) NR_TIME_ITERS;
284 mean /= 10.0;
285
286 for (i = 0; i < NR_TIME_ITERS; i++)
287 dprint(FD_TIME, "cycles[%d]=%llu\n", i,
288 (unsigned long long) cycles[i] / 10);
289
290 avg /= samples;
291 avg = (avg + 5) / 10;
292 dprint(FD_TIME, "avg: %llu\n", (unsigned long long) avg);
293 dprint(FD_TIME, "mean=%f, S=%f\n", mean, S);
294
295 cycles_per_usec = avg;
296 inv_cycles_per_usec = 16777216UL / cycles_per_usec;
297 dprint(FD_TIME, "inv_cycles_per_usec=%lu\n", inv_cycles_per_usec);
298 return 0;
299}
300#else
301static int calibrate_cpu_clock(void)
302{
303#ifdef ARCH_CPU_CLOCK_CYCLES_PER_USEC
304 return 0;
305#else
306 return 1;
307#endif
308}
309#endif // ARCH_HAVE_CPU_CLOCK
310
311#ifndef CONFIG_TLS_THREAD
312void fio_local_clock_init(int is_thread)
313{
314 struct tv_valid *t;
315
316 t = calloc(1, sizeof(*t));
317 if (pthread_setspecific(tv_tls_key, t)) {
318 log_err("fio: can't set TLS key\n");
319 assert(0);
320 }
321}
322
323static void kill_tv_tls_key(void *data)
324{
325 free(data);
326}
327#else
328void fio_local_clock_init(int is_thread)
329{
330}
331#endif
332
333void fio_clock_init(void)
334{
335 if (fio_clock_source == fio_clock_source_inited)
336 return;
337
338#ifndef CONFIG_TLS_THREAD
339 if (pthread_key_create(&tv_tls_key, kill_tv_tls_key))
340 log_err("fio: can't create TLS key\n");
341#endif
342
343 fio_clock_source_inited = fio_clock_source;
344
345 if (calibrate_cpu_clock())
346 tsc_reliable = 0;
347
348 /*
349 * If the arch sets tsc_reliable != 0, then it must be good enough
350 * to use as THE clock source. For x86 CPUs, this means the TSC
351 * runs at a constant rate and is synced across CPU cores.
352 */
353 if (tsc_reliable) {
354 if (!fio_clock_source_set)
355 fio_clock_source = CS_CPUCLOCK;
356 } else if (fio_clock_source == CS_CPUCLOCK)
357 log_info("fio: clocksource=cpu may not be reliable\n");
358}
359
360uint64_t utime_since(const struct timeval *s, const struct timeval *e)
361{
362 long sec, usec;
363 uint64_t ret;
364
365 sec = e->tv_sec - s->tv_sec;
366 usec = e->tv_usec - s->tv_usec;
367 if (sec > 0 && usec < 0) {
368 sec--;
369 usec += 1000000;
370 }
371
372 /*
373 * time warp bug on some kernels?
374 */
375 if (sec < 0 || (sec == 0 && usec < 0))
376 return 0;
377
378 ret = sec * 1000000ULL + usec;
379
380 return ret;
381}
382
383uint64_t utime_since_now(const struct timeval *s)
384{
385 struct timeval t;
386
387 fio_gettime(&t, NULL);
388 return utime_since(s, &t);
389}
390
391uint64_t mtime_since(const struct timeval *s, const struct timeval *e)
392{
393 long sec, usec, ret;
394
395 sec = e->tv_sec - s->tv_sec;
396 usec = e->tv_usec - s->tv_usec;
397 if (sec > 0 && usec < 0) {
398 sec--;
399 usec += 1000000;
400 }
401
402 if (sec < 0 || (sec == 0 && usec < 0))
403 return 0;
404
405 sec *= 1000UL;
406 usec /= 1000UL;
407 ret = sec + usec;
408
409 return ret;
410}
411
412uint64_t mtime_since_now(const struct timeval *s)
413{
414 struct timeval t;
415 void *p = __builtin_return_address(0);
416
417 fio_gettime(&t, p);
418 return mtime_since(s, &t);
419}
420
421uint64_t time_since_now(const struct timeval *s)
422{
423 return mtime_since_now(s) / 1000;
424}
425
426#if defined(FIO_HAVE_CPU_AFFINITY) && defined(ARCH_HAVE_CPU_CLOCK) && \
427 defined(CONFIG_SFAA)
428
429#define CLOCK_ENTRIES 100000
430
431struct clock_entry {
432 uint32_t seq;
433 uint32_t cpu;
434 uint64_t tsc;
435};
436
437struct clock_thread {
438 pthread_t thread;
439 int cpu;
440 pthread_mutex_t lock;
441 pthread_mutex_t started;
442 uint32_t *seq;
443 struct clock_entry *entries;
444};
445
446static inline uint32_t atomic32_inc_return(uint32_t *seq)
447{
448 return 1 + __sync_fetch_and_add(seq, 1);
449}
450
451static void *clock_thread_fn(void *data)
452{
453 struct clock_thread *t = data;
454 struct clock_entry *c;
455 os_cpu_mask_t cpu_mask;
456 uint32_t last_seq;
457 int i;
458
459 memset(&cpu_mask, 0, sizeof(cpu_mask));
460 fio_cpu_set(&cpu_mask, t->cpu);
461
462 if (fio_setaffinity(gettid(), cpu_mask) == -1) {
463 log_err("clock setaffinity failed\n");
464 return (void *) 1;
465 }
466
467 pthread_mutex_lock(&t->lock);
468 pthread_mutex_unlock(&t->started);
469
470 last_seq = 0;
471 c = &t->entries[0];
472 for (i = 0; i < CLOCK_ENTRIES; i++, c++) {
473 uint32_t seq;
474 uint64_t tsc;
475
476 c->cpu = t->cpu;
477 do {
478 seq = atomic32_inc_return(t->seq);
479 if (seq < last_seq)
480 break;
481 tsc = get_cpu_clock();
482 } while (seq != *t->seq);
483
484 c->seq = seq;
485 c->tsc = tsc;
486 }
487
488 log_info("cs: cpu%3d: %llu clocks seen\n", t->cpu,
489 (unsigned long long) t->entries[i - 1].tsc - t->entries[0].tsc);
490
491 /*
492 * The most common platform clock breakage is returning zero
493 * indefinitely. Check for that and return failure.
494 */
495 if (!t->entries[i - 1].tsc && !t->entries[0].tsc)
496 return (void *) 1;
497
498 return NULL;
499}
500
501static int clock_cmp(const void *p1, const void *p2)
502{
503 const struct clock_entry *c1 = p1;
504 const struct clock_entry *c2 = p2;
505
506 if (c1->seq == c2->seq)
507 log_err("cs: bug in atomic sequence!\n");
508
509 return c1->seq - c2->seq;
510}
511
512int fio_monotonic_clocktest(void)
513{
514 struct clock_thread *cthreads;
515 unsigned int nr_cpus = cpus_online();
516 struct clock_entry *entries;
517 unsigned long tentries, failed = 0;
518 struct clock_entry *prev, *this;
519 uint32_t seq = 0;
520 unsigned int i;
521
522 log_info("cs: reliable_tsc: %s\n", tsc_reliable ? "yes" : "no");
523
524#ifdef FIO_INC_DEBUG
525 fio_debug |= 1U << FD_TIME;
526#endif
527 calibrate_cpu_clock();
528#ifdef FIO_INC_DEBUG
529 fio_debug &= ~(1U << FD_TIME);
530#endif
531
532 cthreads = malloc(nr_cpus * sizeof(struct clock_thread));
533 tentries = CLOCK_ENTRIES * nr_cpus;
534 entries = malloc(tentries * sizeof(struct clock_entry));
535
536 log_info("cs: Testing %u CPUs\n", nr_cpus);
537
538 for (i = 0; i < nr_cpus; i++) {
539 struct clock_thread *t = &cthreads[i];
540
541 t->cpu = i;
542 t->seq = &seq;
543 t->entries = &entries[i * CLOCK_ENTRIES];
544 pthread_mutex_init(&t->lock, NULL);
545 pthread_mutex_init(&t->started, NULL);
546 pthread_mutex_lock(&t->lock);
547 if (pthread_create(&t->thread, NULL, clock_thread_fn, t)) {
548 failed++;
549 nr_cpus = i;
550 break;
551 }
552 }
553
554 for (i = 0; i < nr_cpus; i++) {
555 struct clock_thread *t = &cthreads[i];
556
557 pthread_mutex_lock(&t->started);
558 }
559
560 for (i = 0; i < nr_cpus; i++) {
561 struct clock_thread *t = &cthreads[i];
562
563 pthread_mutex_unlock(&t->lock);
564 }
565
566 for (i = 0; i < nr_cpus; i++) {
567 struct clock_thread *t = &cthreads[i];
568 void *ret;
569
570 pthread_join(t->thread, &ret);
571 if (ret)
572 failed++;
573 }
574 free(cthreads);
575
576 if (failed) {
577 log_err("Clocksource test: %lu threads failed\n", failed);
578 goto err;
579 }
580
581 qsort(entries, tentries, sizeof(struct clock_entry), clock_cmp);
582
583 for (failed = i = 0; i < tentries; i++) {
584 this = &entries[i];
585
586 if (!i) {
587 prev = this;
588 continue;
589 }
590
591 if (prev->tsc > this->tsc) {
592 uint64_t diff = prev->tsc - this->tsc;
593
594 log_info("cs: CPU clock mismatch (diff=%llu):\n",
595 (unsigned long long) diff);
596 log_info("\t CPU%3u: TSC=%llu, SEQ=%u\n", prev->cpu, (unsigned long long) prev->tsc, prev->seq);
597 log_info("\t CPU%3u: TSC=%llu, SEQ=%u\n", this->cpu, (unsigned long long) this->tsc, this->seq);
598 failed++;
599 }
600
601 prev = this;
602 }
603
604 if (failed)
605 log_info("cs: Failed: %lu\n", failed);
606 else
607 log_info("cs: Pass!\n");
608
609err:
610 free(entries);
611 return !!failed;
612}
613
614#else /* defined(FIO_HAVE_CPU_AFFINITY) && defined(ARCH_HAVE_CPU_CLOCK) */
615
616int fio_monotonic_clocktest(void)
617{
618 log_info("cs: current platform does not support CPU clocks\n");
619 return 0;
620}
621
622#endif