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;       /* Offset added for unit tests. */
  48     bool stopped;               /* Disables real-time updates if true.  */
  49
  50     struct timespec cache;      /* Last time read from kernel. */
  51 };
  52
  53 /* Our clocks. */
  54 static struct clock monotonic_clock; /* CLOCK_MONOTONIC, if available. */
  55 static struct clock wall_clock;      /* CLOCK_REALTIME. */
  56
  57 /* The monotonic time at which the time module was initialized. */
  58 static long long int boot_time;
  59
  60 /* Monotonic time in milliseconds at which to die with SIGALRM (if not
  61  * LLONG_MAX). */
  62 static long long int deadline = LLONG_MAX;
  63
  64 /* Monotonic time, in milliseconds, at which the last call to time_poll() woke
  65  * up. */
  66 DEFINE_STATIC_PER_THREAD_DATA(long long int, last_wakeup, 0);
  67
  68 static void log_poll_interval(long long int last_wakeup);
  69 static struct rusage *get_recent_rusage(void);
  70 static void refresh_rusage(void);
  71 static void timespec_add(struct timespec *sum,
  72                          const struct timespec *a, const struct timespec *b);
  73
  74 static void
  75 init_clock(struct clock *c, clockid_t id)
  76 {
  77     memset(c, 0, sizeof *c);
  78     c->id = id;
  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 void
 323 log_poll_interval(long long int last_wakeup)
 324 {
 325     long long int interval = time_msec() - last_wakeup;
 326
 327     if (interval >= 1000
 328         && !monotonic_clock.warp.tv_sec
 329         && !monotonic_clock.warp.tv_nsec) {
 330         const struct rusage *last_rusage = get_recent_rusage();
 331         struct rusage rusage;
 332
 333         getrusage(RUSAGE_SELF, &rusage);
 334         VLOG_WARN("Unreasonably long %lldms poll interval"
 335                   " (%lldms user, %lldms system)",
 336                   interval,
 337                   timeval_diff_msec(&rusage.ru_utime,
 338                                     &last_rusage->ru_utime),
 339                   timeval_diff_msec(&rusage.ru_stime,
 340                                     &last_rusage->ru_stime));
 341         if (rusage.ru_minflt > last_rusage->ru_minflt
 342             || rusage.ru_majflt > last_rusage->ru_majflt) {
 343             VLOG_WARN("faults: %ld minor, %ld major",
 344                       rusage.ru_minflt - last_rusage->ru_minflt,
 345                       rusage.ru_majflt - last_rusage->ru_majflt);
 346         }
 347         if (rusage.ru_inblock > last_rusage->ru_inblock
 348             || rusage.ru_oublock > last_rusage->ru_oublock) {
 349             VLOG_WARN("disk: %ld reads, %ld writes",
 350                       rusage.ru_inblock - last_rusage->ru_inblock,
 351                       rusage.ru_oublock - last_rusage->ru_oublock);
 352         }
 353         if (rusage.ru_nvcsw > last_rusage->ru_nvcsw
 354             || rusage.ru_nivcsw > last_rusage->ru_nivcsw) {
 355             VLOG_WARN("context switches: %ld voluntary, %ld involuntary",
 356                       rusage.ru_nvcsw - last_rusage->ru_nvcsw,
 357                       rusage.ru_nivcsw - last_rusage->ru_nivcsw);
 358         }
 359         coverage_log();
 360     }
 361 }
 362 \f
 363 /* CPU usage tracking. */
 364
 365 struct cpu_usage {
 366     long long int when;         /* Time that this sample was taken. */
 367     unsigned long long int cpu; /* Total user+system CPU usage when sampled. */
 368 };
 369
 370 struct cpu_tracker {
 371     struct cpu_usage older;
 372     struct cpu_usage newer;
 373     int cpu_usage;
 374
 375     struct rusage recent_rusage;
 376 };
 377 DEFINE_PER_THREAD_MALLOCED_DATA(struct cpu_tracker *, cpu_tracker_var);
 378
 379 static struct cpu_tracker *
 380 get_cpu_tracker(void)
 381 {
 382     struct cpu_tracker *t = cpu_tracker_var_get();
 383     if (!t) {
 384         t = xzalloc(sizeof *t);
 385         t->older.when = LLONG_MIN;
 386         t->newer.when = LLONG_MIN;
 387         cpu_tracker_var_set_unsafe(t);
 388     }
 389     return t;
 390 }
 391
 392 static struct rusage *
 393 get_recent_rusage(void)
 394 {
 395     return &get_cpu_tracker()->recent_rusage;
 396 }
 397
 398 static int
 399 getrusage_thread(struct rusage *rusage OVS_UNUSED)
 400 {
 401 #ifdef RUSAGE_THREAD
 402     return getrusage(RUSAGE_THREAD, rusage);
 403 #else
 404     errno = EINVAL;
 405     return -1;
 406 #endif
 407 }
 408
 409 static void
 410 refresh_rusage(void)
 411 {
 412     struct cpu_tracker *t = get_cpu_tracker();
 413     struct rusage *recent_rusage = &t->recent_rusage;
 414
 415     if (!getrusage_thread(recent_rusage)) {
 416         long long int now = time_msec();
 417         if (now >= t->newer.when + 3 * 1000) {
 418             t->older = t->newer;
 419             t->newer.when = now;
 420             t->newer.cpu = (timeval_to_msec(&recent_rusage->ru_utime) +
 421                             timeval_to_msec(&recent_rusage->ru_stime));
 422
 423             if (t->older.when != LLONG_MIN && t->newer.cpu > t->older.cpu) {
 424                 unsigned int dividend = t->newer.cpu - t->older.cpu;
 425                 unsigned int divisor = (t->newer.when - t->older.when) / 100;
 426                 t->cpu_usage = divisor > 0 ? dividend / divisor : -1;
 427             } else {
 428                 t->cpu_usage = -1;
 429             }
 430         }
 431     }
 432 }
 433
 434 /* Returns an estimate of this process's CPU usage, as a percentage, over the
 435  * past few seconds of wall-clock time.  Returns -1 if no estimate is available
 436  * (which will happen if the process has not been running long enough to have
 437  * an estimate, and can happen for other reasons as well). */
 438 int
 439 get_cpu_usage(void)
 440 {
 441     return get_cpu_tracker()->cpu_usage;
 442 }
 443 \f
 444 /* Unixctl interface. */
 445
 446 /* "time/stop" stops the monotonic time returned by e.g. time_msec() from
 447  * advancing, except due to later calls to "time/warp". */
 448 static void
 449 timeval_stop_cb(struct unixctl_conn *conn,
 450                  int argc OVS_UNUSED, const char *argv[] OVS_UNUSED,
 451                  void *aux OVS_UNUSED)
 452 {
 453     ovs_rwlock_wrlock(&monotonic_clock.rwlock);
 454     monotonic_clock.stopped = true;
 455     xclock_gettime(monotonic_clock.id, &monotonic_clock.cache);
 456     ovs_rwlock_unlock(&monotonic_clock.rwlock);
 457
 458     unixctl_command_reply(conn, NULL);
 459 }
 460
 461 /* "time/warp MSECS" advances the current monotonic time by the specified
 462  * number of milliseconds.  Unless "time/stop" has also been executed, the
 463  * monotonic clock continues to tick forward at the normal rate afterward.
 464  *
 465  * Does not affect wall clock readings. */
 466 static void
 467 timeval_warp_cb(struct unixctl_conn *conn,
 468                 int argc OVS_UNUSED, const char *argv[], void *aux OVS_UNUSED)
 469 {
 470     struct timespec ts;
 471     int msecs;
 472
 473     msecs = atoi(argv[1]);
 474     if (msecs <= 0) {
 475         unixctl_command_reply_error(conn, "invalid MSECS");
 476         return;
 477     }
 478
 479     ts.tv_sec = msecs / 1000;
 480     ts.tv_nsec = (msecs % 1000) * 1000 * 1000;
 481
 482     ovs_rwlock_wrlock(&monotonic_clock.rwlock);
 483     timespec_add(&monotonic_clock.warp, &monotonic_clock.warp, &ts);
 484     ovs_rwlock_unlock(&monotonic_clock.rwlock);
 485
 486     unixctl_command_reply(conn, "warped");
 487 }
 488
 489 void
 490 timeval_dummy_register(void)
 491 {
 492     unixctl_command_register("time/stop", "", 0, 0, timeval_stop_cb, NULL);
 493     unixctl_command_register("time/warp", "MSECS", 1, 1,
 494                              timeval_warp_cb, NULL);
 495 }