lib/timeval.c

   1 /*
   2  * Copyright (c) 2008, 2009, 2010, 2011, 2012 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 <assert.h>
  20 #include <errno.h>
  21 #include <poll.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 "fatal-signal.h"
  31 #include "signals.h"
  32 #include "unixctl.h"
  33 #include "util.h"
  34 #include "vlog.h"
  35
  36 VLOG_DEFINE_THIS_MODULE(timeval);
  37
  38 /* The clock to use for measuring time intervals.  This is CLOCK_MONOTONIC by
  39  * preference, but on systems that don't have a monotonic clock we fall back
  40  * to CLOCK_REALTIME. */
  41 static clockid_t monotonic_clock;
  42
  43 /* Has a timer tick occurred?
  44  *
  45  * We initialize these to true to force time_init() to get called on the first
  46  * call to time_msec() or another function that queries the current time. */
  47 static volatile sig_atomic_t wall_tick = true;
  48 static volatile sig_atomic_t monotonic_tick = true;
  49
  50 /* The current time, as of the last refresh. */
  51 static struct timespec wall_time;
  52 static struct timespec monotonic_time;
  53
  54 /* The monotonic time at which the time module was initialized. */
  55 static long long int boot_time;
  56
  57 /* features for use by unit tests. */
  58 static struct timespec warp_offset; /* Offset added to monotonic_time. */
  59 static bool time_stopped;           /* Disables real-time updates, if true. */
  60
  61 /* Time at which to die with SIGALRM (if not TIME_MIN). */
  62 static time_t deadline = TIME_MIN;
  63
  64 static void set_up_timer(void);
  65 static void set_up_signal(int flags);
  66 static void sigalrm_handler(int);
  67 static void refresh_wall_if_ticked(void);
  68 static void refresh_monotonic_if_ticked(void);
  69 static time_t time_add(time_t, time_t);
  70 static void block_sigalrm(sigset_t *);
  71 static void unblock_sigalrm(const sigset_t *);
  72 static void log_poll_interval(long long int last_wakeup);
  73 static struct rusage *get_recent_rusage(void);
  74 static void refresh_rusage(void);
  75 static void timespec_add(struct timespec *sum,
  76                          const struct timespec *a, const struct timespec *b);
  77
  78 /* Initializes the timetracking module, if not already initialized. */
  79 static void
  80 time_init(void)
  81 {
  82     static bool inited;
  83     if (inited) {
  84         return;
  85     }
  86     inited = true;
  87
  88     coverage_init();
  89
  90     if (!clock_gettime(CLOCK_MONOTONIC, &monotonic_time)) {
  91         monotonic_clock = CLOCK_MONOTONIC;
  92     } else {
  93         monotonic_clock = CLOCK_REALTIME;
  94         VLOG_DBG("monotonic timer not available");
  95     }
  96
  97     set_up_signal(SA_RESTART);
  98     set_up_timer();
  99     boot_time = time_msec();
 100 }
 101
 102 static void
 103 set_up_signal(int flags)
 104 {
 105     struct sigaction sa;
 106
 107     memset(&sa, 0, sizeof sa);
 108     sa.sa_handler = sigalrm_handler;
 109     sigemptyset(&sa.sa_mask);
 110     sa.sa_flags = flags;
 111     xsigaction(SIGALRM, &sa, NULL);
 112 }
 113
 114 /* Remove SA_RESTART from the flags for SIGALRM, so that any system call that
 115  * is interrupted by the periodic timer interrupt will return EINTR instead of
 116  * continuing after the signal handler returns.
 117  *
 118  * time_disable_restart() and time_enable_restart() may be usefully wrapped
 119  * around function calls that might otherwise block forever unless interrupted
 120  * by a signal, e.g.:
 121  *
 122  *   time_disable_restart();
 123  *   fcntl(fd, F_SETLKW, &lock);
 124  *   time_enable_restart();
 125  */
 126 void
 127 time_disable_restart(void)
 128 {
 129     time_init();
 130     set_up_signal(0);
 131 }
 132
 133 /* Add SA_RESTART to the flags for SIGALRM, so that any system call that
 134  * is interrupted by the periodic timer interrupt will continue after the
 135  * signal handler returns instead of returning EINTR. */
 136 void
 137 time_enable_restart(void)
 138 {
 139     time_init();
 140     set_up_signal(SA_RESTART);
 141 }
 142
 143 static void
 144 set_up_timer(void)
 145 {
 146     static timer_t timer_id;    /* "static" to avoid apparent memory leak. */
 147     struct itimerspec itimer;
 148
 149     if (timer_create(monotonic_clock, NULL, &timer_id)) {
 150         VLOG_FATAL("timer_create failed (%s)", strerror(errno));
 151     }
 152
 153     itimer.it_interval.tv_sec = 0;
 154     itimer.it_interval.tv_nsec = TIME_UPDATE_INTERVAL * 1000 * 1000;
 155     itimer.it_value = itimer.it_interval;
 156
 157     if (timer_settime(timer_id, 0, &itimer, NULL)) {
 158         VLOG_FATAL("timer_settime failed (%s)", strerror(errno));
 159     }
 160 }
 161
 162 /* Set up the interval timer, to ensure that time advances even without calling
 163  * time_refresh().
 164  *
 165  * A child created with fork() does not inherit the parent's interval timer, so
 166  * this function needs to be called from the child after fork(). */
 167 void
 168 time_postfork(void)
 169 {
 170     time_init();
 171     set_up_timer();
 172 }
 173
 174 static void
 175 refresh_wall(void)
 176 {
 177     time_init();
 178     clock_gettime(CLOCK_REALTIME, &wall_time);
 179     wall_tick = false;
 180 }
 181
 182 static void
 183 refresh_monotonic(void)
 184 {
 185     time_init();
 186
 187     if (!time_stopped) {
 188         if (monotonic_clock == CLOCK_MONOTONIC) {
 189             clock_gettime(monotonic_clock, &monotonic_time);
 190         } else {
 191             refresh_wall_if_ticked();
 192             monotonic_time = wall_time;
 193         }
 194         timespec_add(&monotonic_time, &monotonic_time, &warp_offset);
 195
 196         monotonic_tick = false;
 197     }
 198 }
 199
 200 /* Forces a refresh of the current time from the kernel.  It is not usually
 201  * necessary to call this function, since the time will be refreshed
 202  * automatically at least every TIME_UPDATE_INTERVAL milliseconds. */
 203 void
 204 time_refresh(void)
 205 {
 206     wall_tick = monotonic_tick = true;
 207 }
 208
 209 /* Returns a monotonic timer, in seconds. */
 210 time_t
 211 time_now(void)
 212 {
 213     refresh_monotonic_if_ticked();
 214     return monotonic_time.tv_sec;
 215 }
 216
 217 /* Same as time_now() except does not write to static variables, for use in
 218  * signal handlers.  */
 219 static time_t
 220 time_now_sig(void)
 221 {
 222     struct timespec cur_time;
 223
 224     clock_gettime(monotonic_clock, &cur_time);
 225     return cur_time.tv_sec;
 226 }
 227
 228 /* Returns the current time, in seconds. */
 229 time_t
 230 time_wall(void)
 231 {
 232     refresh_wall_if_ticked();
 233     return wall_time.tv_sec;
 234 }
 235
 236 /* Returns a monotonic timer, in ms (within TIME_UPDATE_INTERVAL ms). */
 237 long long int
 238 time_msec(void)
 239 {
 240     refresh_monotonic_if_ticked();
 241     return timespec_to_msec(&monotonic_time);
 242 }
 243
 244 /* Returns the current time, in ms (within TIME_UPDATE_INTERVAL ms). */
 245 long long int
 246 time_wall_msec(void)
 247 {
 248     refresh_wall_if_ticked();
 249     return timespec_to_msec(&wall_time);
 250 }
 251
 252 /* Stores a monotonic timer, accurate within TIME_UPDATE_INTERVAL ms, into
 253  * '*ts'. */
 254 void
 255 time_timespec(struct timespec *ts)
 256 {
 257     refresh_monotonic_if_ticked();
 258     *ts = monotonic_time;
 259 }
 260
 261 /* Stores the current time, accurate within TIME_UPDATE_INTERVAL ms, into
 262  * '*ts'. */
 263 void
 264 time_wall_timespec(struct timespec *ts)
 265 {
 266     refresh_wall_if_ticked();
 267     *ts = wall_time;
 268 }
 269
 270 /* Configures the program to die with SIGALRM 'secs' seconds from now, if
 271  * 'secs' is nonzero, or disables the feature if 'secs' is zero. */
 272 void
 273 time_alarm(unsigned int secs)
 274 {
 275     sigset_t oldsigs;
 276
 277     time_init();
 278     block_sigalrm(&oldsigs);
 279     deadline = secs ? time_add(time_now(), secs) : TIME_MIN;
 280     unblock_sigalrm(&oldsigs);
 281 }
 282
 283 /* Like poll(), except:
 284  *
 285  *      - The timeout is specified as an absolute time, as defined by
 286  *        time_msec(), instead of a duration.
 287  *
 288  *      - On error, returns a negative error code (instead of setting errno).
 289  *
 290  *      - If interrupted by a signal, retries automatically until the original
 291  *        timeout is reached.  (Because of this property, this function will
 292  *        never return -EINTR.)
 293  *
 294  *      - As a side effect, refreshes the current time (like time_refresh()).
 295  *
 296  * Stores the number of milliseconds elapsed during poll in '*elapsed'. */
 297 int
 298 time_poll(struct pollfd *pollfds, int n_pollfds, long long int timeout_when,
 299           int *elapsed)
 300 {
 301     static long long int last_wakeup;
 302     long long int start;
 303     sigset_t oldsigs;
 304     bool blocked;
 305     int retval;
 306
 307     time_refresh();
 308     log_poll_interval(last_wakeup);
 309     coverage_clear();
 310     start = time_msec();
 311     blocked = false;
 312     for (;;) {
 313         long long int now = time_msec();
 314         int time_left;
 315
 316         if (now >= timeout_when) {
 317             time_left = 0;
 318         } else if ((unsigned long long int) timeout_when - now > INT_MAX) {
 319             time_left = INT_MAX;
 320         } else {
 321             time_left = timeout_when - now;
 322         }
 323
 324         retval = poll(pollfds, n_pollfds, time_left);
 325         if (retval < 0) {
 326             retval = -errno;
 327         }
 328         time_refresh();
 329         if (retval != -EINTR) {
 330             break;
 331         }
 332
 333         if (!blocked && deadline == TIME_MIN) {
 334             block_sigalrm(&oldsigs);
 335             blocked = true;
 336         }
 337     }
 338     if (blocked) {
 339         unblock_sigalrm(&oldsigs);
 340     }
 341     last_wakeup = time_msec();
 342     refresh_rusage();
 343     *elapsed = last_wakeup - start;
 344     return retval;
 345 }
 346
 347 /* Returns the sum of 'a' and 'b', with saturation on overflow or underflow. */
 348 static time_t
 349 time_add(time_t a, time_t b)
 350 {
 351     return (a >= 0
 352             ? (b > TIME_MAX - a ? TIME_MAX : a + b)
 353             : (b < TIME_MIN - a ? TIME_MIN : a + b));
 354 }
 355
 356 static void
 357 sigalrm_handler(int sig_nr)
 358 {
 359     wall_tick = true;
 360     monotonic_tick = true;
 361     if (deadline != TIME_MIN && time_now_sig() > deadline) {
 362         fatal_signal_handler(sig_nr);
 363     }
 364 }
 365
 366 static void
 367 refresh_wall_if_ticked(void)
 368 {
 369     if (wall_tick) {
 370         refresh_wall();
 371     }
 372 }
 373
 374 static void
 375 refresh_monotonic_if_ticked(void)
 376 {
 377     if (monotonic_tick) {
 378         refresh_monotonic();
 379     }
 380 }
 381
 382 static void
 383 block_sigalrm(sigset_t *oldsigs)
 384 {
 385     sigset_t sigalrm;
 386     sigemptyset(&sigalrm);
 387     sigaddset(&sigalrm, SIGALRM);
 388     xsigprocmask(SIG_BLOCK, &sigalrm, oldsigs);
 389 }
 390
 391 static void
 392 unblock_sigalrm(const sigset_t *oldsigs)
 393 {
 394     xsigprocmask(SIG_SETMASK, oldsigs, NULL);
 395 }
 396
 397 long long int
 398 timespec_to_msec(const struct timespec *ts)
 399 {
 400     return (long long int) ts->tv_sec * 1000 + ts->tv_nsec / (1000 * 1000);
 401 }
 402
 403 long long int
 404 timeval_to_msec(const struct timeval *tv)
 405 {
 406     return (long long int) tv->tv_sec * 1000 + tv->tv_usec / 1000;
 407 }
 408
 409 /* Returns the monotonic time at which the "time" module was initialized, in
 410  * milliseconds(). */
 411 long long int
 412 time_boot_msec(void)
 413 {
 414     time_init();
 415     return boot_time;
 416 }
 417
 418 void
 419 xgettimeofday(struct timeval *tv)
 420 {
 421     if (gettimeofday(tv, NULL) == -1) {
 422         VLOG_FATAL("gettimeofday failed (%s)", strerror(errno));
 423     }
 424 }
 425
 426 static long long int
 427 timeval_diff_msec(const struct timeval *a, const struct timeval *b)
 428 {
 429     return timeval_to_msec(a) - timeval_to_msec(b);
 430 }
 431
 432 static void
 433 timespec_add(struct timespec *sum,
 434              const struct timespec *a,
 435              const struct timespec *b)
 436 {
 437     struct timespec tmp;
 438
 439     tmp.tv_sec = a->tv_sec + b->tv_sec;
 440     tmp.tv_nsec = a->tv_nsec + b->tv_nsec;
 441     if (tmp.tv_nsec >= 1000 * 1000 * 1000) {
 442         tmp.tv_nsec -= 1000 * 1000 * 1000;
 443         tmp.tv_sec++;
 444     }
 445
 446     *sum = tmp;
 447 }
 448
 449 static void
 450 log_poll_interval(long long int last_wakeup)
 451 {
 452     static unsigned int mean_interval; /* In 16ths of a millisecond. */
 453     static unsigned int n_samples;
 454
 455     long long int now;
 456     unsigned int interval;      /* In 16ths of a millisecond. */
 457
 458     /* Compute interval from last wakeup to now in 16ths of a millisecond,
 459      * capped at 10 seconds (16000 in this unit). */
 460     now = time_msec();
 461     interval = MIN(10000, now - last_wakeup) << 4;
 462
 463     /* Warn if we took too much time between polls: at least 50 ms and at least
 464      * 8X the mean interval. */
 465     if (n_samples > 10 && interval > mean_interval * 8 && interval > 50 * 16) {
 466         static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 3);
 467
 468         if (!VLOG_DROP_WARN(&rl)) {
 469             const struct rusage *last_rusage = get_recent_rusage();
 470             struct rusage rusage;
 471
 472             getrusage(RUSAGE_SELF, &rusage);
 473             VLOG_WARN("%lld ms poll interval (%lld ms user, %lld ms system) "
 474                       "is over %u times the weighted mean interval %u ms "
 475                       "(%u samples)",
 476                       now - last_wakeup,
 477                       timeval_diff_msec(&rusage.ru_utime,
 478                                         &last_rusage->ru_utime),
 479                       timeval_diff_msec(&rusage.ru_stime,
 480                                         &last_rusage->ru_stime),
 481                       interval / mean_interval,
 482                       (mean_interval + 8) / 16, n_samples);
 483             if (rusage.ru_minflt > last_rusage->ru_minflt
 484                 || rusage.ru_majflt > last_rusage->ru_majflt) {
 485                 VLOG_WARN("faults: %ld minor, %ld major",
 486                           rusage.ru_minflt - last_rusage->ru_minflt,
 487                           rusage.ru_majflt - last_rusage->ru_majflt);
 488             }
 489             if (rusage.ru_inblock > last_rusage->ru_inblock
 490                 || rusage.ru_oublock > last_rusage->ru_oublock) {
 491                 VLOG_WARN("disk: %ld reads, %ld writes",
 492                           rusage.ru_inblock - last_rusage->ru_inblock,
 493                           rusage.ru_oublock - last_rusage->ru_oublock);
 494             }
 495             if (rusage.ru_nvcsw > last_rusage->ru_nvcsw
 496                 || rusage.ru_nivcsw > last_rusage->ru_nivcsw) {
 497                 VLOG_WARN("context switches: %ld voluntary, %ld involuntary",
 498                           rusage.ru_nvcsw - last_rusage->ru_nvcsw,
 499                           rusage.ru_nivcsw - last_rusage->ru_nivcsw);
 500             }
 501         }
 502         coverage_log();
 503     }
 504
 505     /* Update exponentially weighted moving average.  With these parameters, a
 506      * given value decays to 1% of its value in about 100 time steps.  */
 507     if (n_samples++) {
 508         mean_interval = (mean_interval * 122 + interval * 6 + 64) / 128;
 509     } else {
 510         mean_interval = interval;
 511     }
 512 }
 513 \f
 514 /* CPU usage tracking. */
 515
 516 struct cpu_usage {
 517     long long int when;         /* Time that this sample was taken. */
 518     unsigned long long int cpu; /* Total user+system CPU usage when sampled. */
 519 };
 520
 521 static struct rusage recent_rusage;
 522 static struct cpu_usage older = { LLONG_MIN, 0 };
 523 static struct cpu_usage newer = { LLONG_MIN, 0 };
 524 static int cpu_usage = -1;
 525
 526 static struct rusage *
 527 get_recent_rusage(void)
 528 {
 529     return &recent_rusage;
 530 }
 531
 532 static void
 533 refresh_rusage(void)
 534 {
 535     long long int now;
 536
 537     now = time_msec();
 538     getrusage(RUSAGE_SELF, &recent_rusage);
 539
 540     if (now >= newer.when + 3 * 1000) {
 541         older = newer;
 542         newer.when = now;
 543         newer.cpu = (timeval_to_msec(&recent_rusage.ru_utime) +
 544                      timeval_to_msec(&recent_rusage.ru_stime));
 545
 546         if (older.when != LLONG_MIN && newer.cpu > older.cpu) {
 547             unsigned int dividend = newer.cpu - older.cpu;
 548             unsigned int divisor = (newer.when - older.when) / 100;
 549             cpu_usage = divisor > 0 ? dividend / divisor : -1;
 550         } else {
 551             cpu_usage = -1;
 552         }
 553     }
 554 }
 555
 556 /* Returns an estimate of this process's CPU usage, as a percentage, over the
 557  * past few seconds of wall-clock time.  Returns -1 if no estimate is available
 558  * (which will happen if the process has not been running long enough to have
 559  * an estimate, and can happen for other reasons as well). */
 560 int
 561 get_cpu_usage(void)
 562 {
 563     return cpu_usage;
 564 }
 565 \f
 566 /* Unixctl interface. */
 567
 568 /* "time/stop" stops the monotonic time returned by e.g. time_msec() from
 569  * advancing, except due to later calls to "time/warp". */
 570 static void
 571 timeval_stop_cb(struct unixctl_conn *conn,
 572                  int argc OVS_UNUSED, const char *argv[] OVS_UNUSED,
 573                  void *aux OVS_UNUSED)
 574 {
 575     time_stopped = true;
 576     unixctl_command_reply(conn, NULL);
 577 }
 578
 579 /* "time/warp MSECS" advances the current monotonic time by the specified
 580  * number of milliseconds.  Unless "time/stop" has also been executed, the
 581  * monotonic clock continues to tick forward at the normal rate afterward.
 582  *
 583  * Does not affect wall clock readings. */
 584 static void
 585 timeval_warp_cb(struct unixctl_conn *conn,
 586                 int argc OVS_UNUSED, const char *argv[], void *aux OVS_UNUSED)
 587 {
 588     struct timespec ts;
 589     int msecs;
 590
 591     msecs = atoi(argv[1]);
 592     if (msecs <= 0) {
 593         unixctl_command_reply_error(conn, "invalid MSECS");
 594         return;
 595     }
 596
 597     ts.tv_sec = msecs / 1000;
 598     ts.tv_nsec = (msecs % 1000) * 1000 * 1000;
 599     timespec_add(&warp_offset, &warp_offset, &ts);
 600     timespec_add(&monotonic_time, &monotonic_time, &ts);
 601     unixctl_command_reply(conn, "warped");
 602 }
 603
 604 void
 605 timeval_dummy_register(void)
 606 {
 607     unixctl_command_register("time/stop", "", 0, 0, timeval_stop_cb, NULL);
 608     unixctl_command_register("time/warp", "MSECS", 1, 1,
 609                              timeval_warp_cb, NULL);
 610 }