gettime.c

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