lib/timeval.c

   1 /*
   2  * Copyright (c) 2008, 2009, 2010, 2011, 2012, 2013 Nicira, Inc.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at:
   7  *
   8  *     http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 #include <config.h>
  18 #include "timeval.h"
  19 #include <errno.h>
  20 #include <poll.h>
  21 #include <pthread.h>
  22 #include <signal.h>
  23 #include <stdlib.h>
  24 #include <string.h>
  25 #include <sys/time.h>
  26 #include <sys/resource.h>
  27 #include <unistd.h>
  28 #include "coverage.h"
  29 #include "dummy.h"
  30 #include "dynamic-string.h"
  31 #include "fatal-signal.h"
  32 #include "hash.h"
  33 #include "hmap.h"
  34 #include "ovs-thread.h"
  35 #include "signals.h"
  36 #include "unixctl.h"
  37 #include "util.h"
  38 #include "vlog.h"
  39
  40 VLOG_DEFINE_THIS_MODULE(timeval);
  41
  42 struct clock {
  43     clockid_t id;               /* CLOCK_MONOTONIC or CLOCK_REALTIME. */
  44
  45     /* Features for use by unit tests.  Protected by 'rwlock'. */
  46     struct ovs_rwlock rwlock;
  47     struct timespec warp OVS_GUARDED;  /* Offset added for unit tests. */
  48     bool stopped OVS_GUARDED;          /* Disable real-time updates if true. */
  49     struct timespec cache OVS_GUARDED; /* Last time read from kernel. */
  50 };
  51
  52 /* Our clocks. */
  53 static struct clock monotonic_clock; /* CLOCK_MONOTONIC, if available. */
  54 static struct clock wall_clock;      /* CLOCK_REALTIME. */
  55
  56 /* The monotonic time at which the time module was initialized. */
  57 static long long int boot_time;
  58
  59 /* Monotonic time in milliseconds at which to die with SIGALRM (if not
  60  * LLONG_MAX). */
  61 static long long int deadline = LLONG_MAX;
  62
  63 /* Monotonic time, in milliseconds, at which the last call to time_poll() woke
  64  * up. */
  65 DEFINE_STATIC_PER_THREAD_DATA(long long int, last_wakeup, 0);
  66
  67 static void log_poll_interval(long long int last_wakeup);
  68 static struct rusage *get_recent_rusage(void);
  69 static void refresh_rusage(void);
  70 static void timespec_add(struct timespec *sum,
  71                          const struct timespec *a, const struct timespec *b);
  72
  73 static void
  74 init_clock(struct clock *c, clockid_t id)
  75 {
  76     memset(c, 0, sizeof *c);
  77     c->id = id;
  78     ovs_rwlock_init(&c->rwlock);
  79     xclock_gettime(c->id, &c->cache);
  80 }
  81
  82 static void
  83 do_init_time(void)
  84 {
  85     struct timespec ts;
  86
  87     coverage_init();
  88
  89     init_clock(&monotonic_clock, (!clock_gettime(CLOCK_MONOTONIC, &ts)
  90                                   ? CLOCK_MONOTONIC
  91                                   : CLOCK_REALTIME));
  92     init_clock(&wall_clock, CLOCK_REALTIME);
  93     boot_time = timespec_to_msec(&monotonic_clock.cache);
  94 }
  95
  96 /* Initializes the timetracking module, if not already initialized. */
  97 static void
  98 time_init(void)
  99 {
 100     static pthread_once_t once = PTHREAD_ONCE_INIT;
 101     pthread_once(&once, do_init_time);
 102 }
 103
 104 static void
 105 time_timespec__(struct clock *c, struct timespec *ts)
 106 {
 107     time_init();
 108
 109     if (!c->stopped) {
 110         xclock_gettime(c->id, ts);
 111     } else {
 112         ovs_rwlock_rdlock(&c->rwlock);
 113         timespec_add(ts, &c->cache, &c->warp);
 114         ovs_rwlock_unlock(&c->rwlock);
 115     }
 116 }
 117
 118 /* Stores a monotonic timer, accurate within TIME_UPDATE_INTERVAL ms, into
 119  * '*ts'. */
 120 void
 121 time_timespec(struct timespec *ts)
 122 {
 123     time_timespec__(&monotonic_clock, ts);
 124 }
 125
 126 /* Stores the current time, accurate within TIME_UPDATE_INTERVAL ms, into
 127  * '*ts'. */
 128 void
 129 time_wall_timespec(struct timespec *ts)
 130 {
 131     time_timespec__(&wall_clock, ts);
 132 }
 133
 134 static time_t
 135 time_sec__(struct clock *c)
 136 {
 137     struct timespec ts;
 138
 139     time_timespec__(c, &ts);
 140     return ts.tv_sec;
 141 }
 142
 143 /* Returns a monotonic timer, in seconds. */
 144 time_t
 145 time_now(void)
 146 {
 147     return time_sec__(&monotonic_clock);
 148 }
 149
 150 /* Returns the current time, in seconds. */
 151 time_t
 152 time_wall(void)
 153 {
 154     return time_sec__(&wall_clock);
 155 }
 156
 157 static long long int
 158 time_msec__(struct clock *c)
 159 {
 160     struct timespec ts;
 161
 162     time_timespec__(c, &ts);
 163     return timespec_to_msec(&ts);
 164 }
 165
 166 /* Returns a monotonic timer, in ms (within TIME_UPDATE_INTERVAL ms). */
 167 long long int
 168 time_msec(void)
 169 {
 170     return time_msec__(&monotonic_clock);
 171 }
 172
 173 /* Returns the current time, in ms (within TIME_UPDATE_INTERVAL ms). */
 174 long long int
 175 time_wall_msec(void)
 176 {
 177     return time_msec__(&wall_clock);
 178 }
 179
 180 /* Configures the program to die with SIGALRM 'secs' seconds from now, if
 181  * 'secs' is nonzero, or disables the feature if 'secs' is zero. */
 182 void
 183 time_alarm(unsigned int secs)
 184 {
 185     long long int now;
 186     long long int msecs;
 187
 188     assert_single_threaded();
 189     time_init();
 190
 191     now = time_msec();
 192     msecs = secs * 1000LL;
 193     deadline = now < LLONG_MAX - msecs ? now + msecs : LLONG_MAX;
 194 }
 195
 196 /* Like poll(), except:
 197  *
 198  *      - The timeout is specified as an absolute time, as defined by
 199  *        time_msec(), instead of a duration.
 200  *
 201  *      - On error, returns a negative error code (instead of setting errno).
 202  *
 203  *      - If interrupted by a signal, retries automatically until the original
 204  *        timeout is reached.  (Because of this property, this function will
 205  *        never return -EINTR.)
 206  *
 207  * Stores the number of milliseconds elapsed during poll in '*elapsed'. */
 208 int
 209 time_poll(struct pollfd *pollfds, int n_pollfds, long long int timeout_when,
 210           int *elapsed)
 211 {
 212     long long int *last_wakeup = last_wakeup_get();
 213     long long int start;
 214     int retval;
 215
 216     time_init();
 217     if (*last_wakeup) {
 218         log_poll_interval(*last_wakeup);
 219     }
 220     coverage_clear();
 221     start = time_msec();
 222
 223     timeout_when = MIN(timeout_when, deadline);
 224
 225     for (;;) {
 226         long long int now = time_msec();
 227         int time_left;
 228
 229         if (now >= timeout_when) {
 230             time_left = 0;
 231         } else if ((unsigned long long int) timeout_when - now > INT_MAX) {
 232             time_left = INT_MAX;
 233         } else {
 234             time_left = timeout_when - now;
 235         }
 236
 237         retval = poll(pollfds, n_pollfds, time_left);
 238         if (retval < 0) {
 239             retval = -errno;
 240         }
 241
 242         if (deadline <= time_msec()) {
 243             fatal_signal_handler(SIGALRM);
 244             if (retval < 0) {
 245                 retval = 0;
 246             }
 247             break;
 248         }
 249
 250         if (retval != -EINTR) {
 251             break;
 252         }
 253     }
 254     *last_wakeup = time_msec();
 255     refresh_rusage();
 256     *elapsed = *last_wakeup - start;
 257     return retval;
 258 }
 259
 260 long long int
 261 timespec_to_msec(const struct timespec *ts)
 262 {
 263     return (long long int) ts->tv_sec * 1000 + ts->tv_nsec / (1000 * 1000);
 264 }
 265
 266 long long int
 267 timeval_to_msec(const struct timeval *tv)
 268 {
 269     return (long long int) tv->tv_sec * 1000 + tv->tv_usec / 1000;
 270 }
 271
 272 /* Returns the monotonic time at which the "time" module was initialized, in
 273  * milliseconds. */
 274 long long int
 275 time_boot_msec(void)
 276 {
 277     time_init();
 278     return boot_time;
 279 }
 280
 281 void
 282 xgettimeofday(struct timeval *tv)
 283 {
 284     if (gettimeofday(tv, NULL) == -1) {
 285         VLOG_FATAL("gettimeofday failed (%s)", ovs_strerror(errno));
 286     }
 287 }
 288
 289 void
 290 xclock_gettime(clock_t id, struct timespec *ts)
 291 {
 292     if (clock_gettime(id, ts) == -1) {
 293         /* It seems like a bad idea to try to use vlog here because it is
 294          * likely to try to check the current time. */
 295         ovs_abort(errno, "xclock_gettime() failed");
 296     }
 297 }
 298
 299 static long long int
 300 timeval_diff_msec(const struct timeval *a, const struct timeval *b)
 301 {
 302     return timeval_to_msec(a) - timeval_to_msec(b);
 303 }
 304
 305 static void
 306 timespec_add(struct timespec *sum,
 307              const struct timespec *a,
 308              const struct timespec *b)
 309 {
 310     struct timespec tmp;
 311
 312     tmp.tv_sec = a->tv_sec + b->tv_sec;
 313     tmp.tv_nsec = a->tv_nsec + b->tv_nsec;
 314     if (tmp.tv_nsec >= 1000 * 1000 * 1000) {
 315         tmp.tv_nsec -= 1000 * 1000 * 1000;
 316         tmp.tv_sec++;
 317     }
 318
 319     *sum = tmp;
 320 }
 321
 322 static bool
 323 is_warped(const struct clock *c)
 324 {
 325     bool warped;
 326
 327     ovs_rwlock_rdlock(&c->rwlock);
 328     warped = monotonic_clock.warp.tv_sec || monotonic_clock.warp.tv_nsec;
 329     ovs_rwlock_unlock(&c->rwlock);
 330
 331     return warped;
 332 }
 333
 334 static void
 335 log_poll_interval(long long int last_wakeup)
 336 {
 337     long long int interval = time_msec() - last_wakeup;
 338
 339     if (interval >= 1000 && !is_warped(&monotonic_clock)) {
 340         const struct rusage *last_rusage = get_recent_rusage();
 341         struct rusage rusage;
 342
 343         getrusage(RUSAGE_SELF, &rusage);
 344         VLOG_WARN("Unreasonably long %lldms poll interval"
 345                   " (%lldms user, %lldms system)",
 346                   interval,
 347                   timeval_diff_msec(&rusage.ru_utime,
 348                                     &last_rusage->ru_utime),
 349                   timeval_diff_msec(&rusage.ru_stime,
 350                                     &last_rusage->ru_stime));
 351         if (rusage.ru_minflt > last_rusage->ru_minflt
 352             || rusage.ru_majflt > last_rusage->ru_majflt) {
 353             VLOG_WARN("faults: %ld minor, %ld major",
 354                       rusage.ru_minflt - last_rusage->ru_minflt,
 355                       rusage.ru_majflt - last_rusage->ru_majflt);
 356         }
 357         if (rusage.ru_inblock > last_rusage->ru_inblock
 358             || rusage.ru_oublock > last_rusage->ru_oublock) {
 359             VLOG_WARN("disk: %ld reads, %ld writes",
 360                       rusage.ru_inblock - last_rusage->ru_inblock,
 361                       rusage.ru_oublock - last_rusage->ru_oublock);
 362         }
 363         if (rusage.ru_nvcsw > last_rusage->ru_nvcsw
 364             || rusage.ru_nivcsw > last_rusage->ru_nivcsw) {
 365             VLOG_WARN("context switches: %ld voluntary, %ld involuntary",
 366                       rusage.ru_nvcsw - last_rusage->ru_nvcsw,
 367                       rusage.ru_nivcsw - last_rusage->ru_nivcsw);
 368         }
 369         coverage_log();
 370     }
 371 }
 372 \f
 373 /* CPU usage tracking. */
 374
 375 struct cpu_usage {
 376     long long int when;         /* Time that this sample was taken. */
 377     unsigned long long int cpu; /* Total user+system CPU usage when sampled. */
 378 };
 379
 380 struct cpu_tracker {
 381     struct cpu_usage older;
 382     struct cpu_usage newer;
 383     int cpu_usage;
 384
 385     struct rusage recent_rusage;
 386 };
 387 DEFINE_PER_THREAD_MALLOCED_DATA(struct cpu_tracker *, cpu_tracker_var);
 388
 389 static struct cpu_tracker *
 390 get_cpu_tracker(void)
 391 {
 392     struct cpu_tracker *t = cpu_tracker_var_get();
 393     if (!t) {
 394         t = xzalloc(sizeof *t);
 395         t->older.when = LLONG_MIN;
 396         t->newer.when = LLONG_MIN;
 397         cpu_tracker_var_set_unsafe(t);
 398     }
 399     return t;
 400 }
 401
 402 static struct rusage *
 403 get_recent_rusage(void)
 404 {
 405     return &get_cpu_tracker()->recent_rusage;
 406 }
 407
 408 static int
 409 getrusage_thread(struct rusage *rusage OVS_UNUSED)
 410 {
 411 #ifdef RUSAGE_THREAD
 412     return getrusage(RUSAGE_THREAD, rusage);
 413 #else
 414     errno = EINVAL;
 415     return -1;
 416 #endif
 417 }
 418
 419 static void
 420 refresh_rusage(void)
 421 {
 422     struct cpu_tracker *t = get_cpu_tracker();
 423     struct rusage *recent_rusage = &t->recent_rusage;
 424
 425     if (!getrusage_thread(recent_rusage)) {
 426         long long int now = time_msec();
 427         if (now >= t->newer.when + 3 * 1000) {
 428             t->older = t->newer;
 429             t->newer.when = now;
 430             t->newer.cpu = (timeval_to_msec(&recent_rusage->ru_utime) +
 431                             timeval_to_msec(&recent_rusage->ru_stime));
 432
 433             if (t->older.when != LLONG_MIN && t->newer.cpu > t->older.cpu) {
 434                 unsigned int dividend = t->newer.cpu - t->older.cpu;
 435                 unsigned int divisor = (t->newer.when - t->older.when) / 100;
 436                 t->cpu_usage = divisor > 0 ? dividend / divisor : -1;
 437             } else {
 438                 t->cpu_usage = -1;
 439             }
 440         }
 441     }
 442 }
 443
 444 /* Returns an estimate of this process's CPU usage, as a percentage, over the
 445  * past few seconds of wall-clock time.  Returns -1 if no estimate is available
 446  * (which will happen if the process has not been running long enough to have
 447  * an estimate, and can happen for other reasons as well). */
 448 int
 449 get_cpu_usage(void)
 450 {
 451     return get_cpu_tracker()->cpu_usage;
 452 }
 453 \f
 454 /* Unixctl interface. */
 455
 456 /* "time/stop" stops the monotonic time returned by e.g. time_msec() from
 457  * advancing, except due to later calls to "time/warp". */
 458 static void
 459 timeval_stop_cb(struct unixctl_conn *conn,
 460                  int argc OVS_UNUSED, const char *argv[] OVS_UNUSED,
 461                  void *aux OVS_UNUSED)
 462 {
 463     ovs_rwlock_wrlock(&monotonic_clock.rwlock);
 464     monotonic_clock.stopped = true;
 465     xclock_gettime(monotonic_clock.id, &monotonic_clock.cache);
 466     ovs_rwlock_unlock(&monotonic_clock.rwlock);
 467
 468     unixctl_command_reply(conn, NULL);
 469 }
 470
 471 /* "time/warp MSECS" advances the current monotonic time by the specified
 472  * number of milliseconds.  Unless "time/stop" has also been executed, the
 473  * monotonic clock continues to tick forward at the normal rate afterward.
 474  *
 475  * Does not affect wall clock readings. */
 476 static void
 477 timeval_warp_cb(struct unixctl_conn *conn,
 478                 int argc OVS_UNUSED, const char *argv[], void *aux OVS_UNUSED)
 479 {
 480     struct timespec ts;
 481     int msecs;
 482
 483     msecs = atoi(argv[1]);
 484     if (msecs <= 0) {
 485         unixctl_command_reply_error(conn, "invalid MSECS");
 486         return;
 487     }
 488
 489     ts.tv_sec = msecs / 1000;
 490     ts.tv_nsec = (msecs % 1000) * 1000 * 1000;
 491
 492     ovs_rwlock_wrlock(&monotonic_clock.rwlock);
 493     timespec_add(&monotonic_clock.warp, &monotonic_clock.warp, &ts);
 494     ovs_rwlock_unlock(&monotonic_clock.rwlock);
 495
 496     unixctl_command_reply(conn, "warped");
 497 }
 498
 499 void
 500 timeval_dummy_register(void)
 501 {
 502     unixctl_command_register("time/stop", "", 0, 0, timeval_stop_cb, NULL);
 503     unixctl_command_register("time/warp", "MSECS", 1, 1,
 504                              timeval_warp_cb, NULL);
 505 }
 506
 507
 508
 509 /* strftime() with an extension for high-resolution timestamps.  Any '#'s in
 510  * 'format' will be replaced by subseconds, e.g. use "%S.###" to obtain results
 511  * like "01.123".  */
 512 size_t
 513 strftime_msec(char *s, size_t max, const char *format,
 514               const struct tm_msec *tm)
 515 {
 516     size_t n;
 517
 518     n = strftime(s, max, format, &tm->tm);
 519     if (n) {
 520         char decimals[4];
 521         char *p;
 522
 523         sprintf(decimals, "%03d", tm->msec);
 524         for (p = strchr(s, '#'); p; p = strchr(p, '#')) {
 525             char *d = decimals;
 526             while (*p == '#')  {
 527                 *p++ = *d ? *d++ : '0';
 528             }
 529         }
 530     }
 531
 532     return n;
 533 }
 534
 535 struct tm_msec *
 536 localtime_msec(long long int now, struct tm_msec *result)
 537 {
 538   time_t now_sec = now / 1000;
 539   localtime_r(&now_sec, &result->tm);
 540   result->msec = now % 1000;
 541   return result;
 542 }
 543
 544 struct tm_msec *
 545 gmtime_msec(long long int now, struct tm_msec *result)
 546 {
 547   time_t now_sec = now / 1000;
 548   gmtime_r(&now_sec, &result->tm);
 549   result->msec = now % 1000;
 550   return result;
 551 }