ef806e7627db162f0e62d0f3fd3aeab7fd70156a
[sliver-openvswitch.git] / lib / timeval.c
1 /*
2  * Copyright (c) 2008, 2009, 2010, 2011, 2012, 2013, 2014 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 "seq.h"
37 #include "unixctl.h"
38 #include "util.h"
39 #include "vlog.h"
40
41 VLOG_DEFINE_THIS_MODULE(timeval);
42
43 #ifdef _WIN32
44 typedef unsigned int clockid_t;
45
46 #ifndef CLOCK_MONOTONIC
47 #define CLOCK_MONOTONIC 1
48 #endif
49
50 #ifndef CLOCK_REALTIME
51 #define CLOCK_REALTIME 2
52 #endif
53
54 /* Number of 100 ns intervals from January 1, 1601 till January 1, 1970. */
55 static ULARGE_INTEGER unix_epoch;
56 #endif /* _WIN32 */
57
58 struct clock {
59     clockid_t id;               /* CLOCK_MONOTONIC or CLOCK_REALTIME. */
60
61     /* Features for use by unit tests.  Protected by 'mutex'. */
62     struct ovs_mutex mutex;
63     atomic_bool slow_path;             /* True if warped or stopped. */
64     struct timespec warp OVS_GUARDED;  /* Offset added for unit tests. */
65     bool stopped OVS_GUARDED;          /* Disable real-time updates if true. */
66     struct timespec cache OVS_GUARDED; /* Last time read from kernel. */
67 };
68
69 /* Our clocks. */
70 static struct clock monotonic_clock; /* CLOCK_MONOTONIC, if available. */
71 static struct clock wall_clock;      /* CLOCK_REALTIME. */
72
73 /* The monotonic time at which the time module was initialized. */
74 static long long int boot_time;
75
76 /* True only when timeval_dummy_register() is called. */
77 static bool timewarp_enabled;
78 /* Reference to the seq struct.  Threads other than main thread can
79  * wait on timewarp_seq and be waken up when time is warped. */
80 static struct seq *timewarp_seq;
81 /* Last value of 'timewarp_seq'. */
82 DEFINE_STATIC_PER_THREAD_DATA(uint64_t, last_seq, 0);
83
84 /* Monotonic time in milliseconds at which to die with SIGALRM (if not
85  * LLONG_MAX). */
86 static long long int deadline = LLONG_MAX;
87
88 /* Monotonic time, in milliseconds, at which the last call to time_poll() woke
89  * up. */
90 DEFINE_STATIC_PER_THREAD_DATA(long long int, last_wakeup, 0);
91
92 static void log_poll_interval(long long int last_wakeup);
93 static struct rusage *get_recent_rusage(void);
94 static void refresh_rusage(void);
95 static void timespec_add(struct timespec *sum,
96                          const struct timespec *a, const struct timespec *b);
97
98 static void
99 init_clock(struct clock *c, clockid_t id)
100 {
101     memset(c, 0, sizeof *c);
102     c->id = id;
103     ovs_mutex_init(&c->mutex);
104     atomic_init(&c->slow_path, false);
105     xclock_gettime(c->id, &c->cache);
106     timewarp_seq = seq_create();
107 }
108
109 static void
110 do_init_time(void)
111 {
112     struct timespec ts;
113
114 #ifdef _WIN32
115     /* Calculate number of 100-nanosecond intervals till 01/01/1970. */
116     SYSTEMTIME unix_epoch_st = { 1970, 1, 0, 1, 0, 0, 0, 0};
117     FILETIME unix_epoch_ft;
118
119     SystemTimeToFileTime(&unix_epoch_st, &unix_epoch_ft);
120     unix_epoch.LowPart = unix_epoch_ft.dwLowDateTime;
121     unix_epoch.HighPart = unix_epoch_ft.dwHighDateTime;
122 #endif
123
124     coverage_init();
125
126     init_clock(&monotonic_clock, (!clock_gettime(CLOCK_MONOTONIC, &ts)
127                                   ? CLOCK_MONOTONIC
128                                   : CLOCK_REALTIME));
129     init_clock(&wall_clock, CLOCK_REALTIME);
130     boot_time = timespec_to_msec(&monotonic_clock.cache);
131 }
132
133 /* Initializes the timetracking module, if not already initialized. */
134 static void
135 time_init(void)
136 {
137     static pthread_once_t once = PTHREAD_ONCE_INIT;
138     pthread_once(&once, do_init_time);
139 }
140
141 static void
142 time_timespec__(struct clock *c, struct timespec *ts)
143 {
144     bool slow_path;
145
146     time_init();
147
148     atomic_read_explicit(&c->slow_path, &slow_path, memory_order_relaxed);
149     if (!slow_path) {
150         xclock_gettime(c->id, ts);
151     } else {
152         struct timespec warp;
153         struct timespec cache;
154         bool stopped;
155
156         ovs_mutex_lock(&c->mutex);
157         stopped = c->stopped;
158         warp = c->warp;
159         cache = c->cache;
160         ovs_mutex_unlock(&c->mutex);
161
162         if (!stopped) {
163             xclock_gettime(c->id, &cache);
164         }
165         timespec_add(ts, &cache, &warp);
166     }
167 }
168
169 /* Stores a monotonic timer, accurate within TIME_UPDATE_INTERVAL ms, into
170  * '*ts'. */
171 void
172 time_timespec(struct timespec *ts)
173 {
174     time_timespec__(&monotonic_clock, ts);
175 }
176
177 /* Stores the current time, accurate within TIME_UPDATE_INTERVAL ms, into
178  * '*ts'. */
179 void
180 time_wall_timespec(struct timespec *ts)
181 {
182     time_timespec__(&wall_clock, ts);
183 }
184
185 static time_t
186 time_sec__(struct clock *c)
187 {
188     struct timespec ts;
189
190     time_timespec__(c, &ts);
191     return ts.tv_sec;
192 }
193
194 /* Returns a monotonic timer, in seconds. */
195 time_t
196 time_now(void)
197 {
198     return time_sec__(&monotonic_clock);
199 }
200
201 /* Returns the current time, in seconds. */
202 time_t
203 time_wall(void)
204 {
205     return time_sec__(&wall_clock);
206 }
207
208 static long long int
209 time_msec__(struct clock *c)
210 {
211     struct timespec ts;
212
213     time_timespec__(c, &ts);
214     return timespec_to_msec(&ts);
215 }
216
217 /* Returns a monotonic timer, in ms (within TIME_UPDATE_INTERVAL ms). */
218 long long int
219 time_msec(void)
220 {
221     return time_msec__(&monotonic_clock);
222 }
223
224 /* Returns the current time, in ms (within TIME_UPDATE_INTERVAL ms). */
225 long long int
226 time_wall_msec(void)
227 {
228     return time_msec__(&wall_clock);
229 }
230
231 /* Configures the program to die with SIGALRM 'secs' seconds from now, if
232  * 'secs' is nonzero, or disables the feature if 'secs' is zero. */
233 void
234 time_alarm(unsigned int secs)
235 {
236     long long int now;
237     long long int msecs;
238
239     assert_single_threaded();
240     time_init();
241
242     now = time_msec();
243     msecs = secs * 1000LL;
244     deadline = now < LLONG_MAX - msecs ? now + msecs : LLONG_MAX;
245 }
246
247 /* Like poll(), except:
248  *
249  *      - The timeout is specified as an absolute time, as defined by
250  *        time_msec(), instead of a duration.
251  *
252  *      - On error, returns a negative error code (instead of setting errno).
253  *
254  *      - If interrupted by a signal, retries automatically until the original
255  *        timeout is reached.  (Because of this property, this function will
256  *        never return -EINTR.)
257  *
258  * Stores the number of milliseconds elapsed during poll in '*elapsed'. */
259 int
260 time_poll(struct pollfd *pollfds, int n_pollfds, HANDLE *handles OVS_UNUSED,
261           long long int timeout_when, int *elapsed)
262 {
263     long long int *last_wakeup = last_wakeup_get();
264     long long int start;
265     int retval = 0;
266
267     time_init();
268     coverage_clear();
269     coverage_run();
270     if (*last_wakeup) {
271         log_poll_interval(*last_wakeup);
272     }
273     start = time_msec();
274
275     timeout_when = MIN(timeout_when, deadline);
276
277     for (;;) {
278         long long int now = time_msec();
279         int time_left;
280
281         if (now >= timeout_when) {
282             time_left = 0;
283         } else if ((unsigned long long int) timeout_when - now > INT_MAX) {
284             time_left = INT_MAX;
285         } else {
286             time_left = timeout_when - now;
287         }
288
289 #ifndef _WIN32
290         retval = poll(pollfds, n_pollfds, time_left);
291         if (retval < 0) {
292             retval = -errno;
293         }
294 #else
295         if (n_pollfds > MAXIMUM_WAIT_OBJECTS) {
296             VLOG_ERR("Cannot handle more than maximum wait objects\n");
297         } else if (n_pollfds != 0) {
298             retval = WaitForMultipleObjects(n_pollfds, handles, FALSE,
299                                             time_left);
300         }
301         if (retval < 0) {
302             /* XXX This will be replace by a win error to errno
303                conversion function */
304             retval = -WSAGetLastError();
305             retval = -EINVAL;
306         }
307 #endif
308
309         if (deadline <= time_msec()) {
310 #ifndef _WIN32
311             fatal_signal_handler(SIGALRM);
312 #else
313             VLOG_ERR("wake up from WaitForMultipleObjects after deadline");
314             fatal_signal_handler(SIGTERM);
315 #endif
316             if (retval < 0) {
317                 retval = 0;
318             }
319             break;
320         }
321
322         if (retval != -EINTR) {
323             break;
324         }
325     }
326     *last_wakeup = time_msec();
327     refresh_rusage();
328     *elapsed = *last_wakeup - start;
329     return retval;
330 }
331
332 long long int
333 timespec_to_msec(const struct timespec *ts)
334 {
335     return (long long int) ts->tv_sec * 1000 + ts->tv_nsec / (1000 * 1000);
336 }
337
338 long long int
339 timeval_to_msec(const struct timeval *tv)
340 {
341     return (long long int) tv->tv_sec * 1000 + tv->tv_usec / 1000;
342 }
343
344 /* Returns the monotonic time at which the "time" module was initialized, in
345  * milliseconds. */
346 long long int
347 time_boot_msec(void)
348 {
349     time_init();
350     return boot_time;
351 }
352
353 #ifdef _WIN32
354 static ULARGE_INTEGER
355 xgetfiletime(void)
356 {
357     ULARGE_INTEGER current_time;
358     FILETIME current_time_ft;
359
360     /* Returns current time in UTC as a 64-bit value representing the number
361      * of 100-nanosecond intervals since January 1, 1601 . */
362     GetSystemTimePreciseAsFileTime(&current_time_ft);
363     current_time.LowPart = current_time_ft.dwLowDateTime;
364     current_time.HighPart = current_time_ft.dwHighDateTime;
365
366     return current_time;
367 }
368
369 static int
370 clock_gettime(clock_t id, struct timespec *ts)
371 {
372     if (id == CLOCK_MONOTONIC) {
373         static LARGE_INTEGER freq;
374         LARGE_INTEGER count;
375         long long int ns;
376
377         if (!freq.QuadPart) {
378             /* Number of counts per second. */
379             QueryPerformanceFrequency(&freq);
380         }
381         /* Total number of counts from a starting point. */
382         QueryPerformanceCounter(&count);
383
384         /* Total nano seconds from a starting point. */
385         ns = (double) count.QuadPart / freq.QuadPart * 1000000000;
386
387         ts->tv_sec = count.QuadPart / freq.QuadPart;
388         ts->tv_nsec = ns % 1000000000;
389     } else if (id == CLOCK_REALTIME) {
390         ULARGE_INTEGER current_time = xgetfiletime();
391
392         /* Time from Epoch to now. */
393         ts->tv_sec = (current_time.QuadPart - unix_epoch.QuadPart) / 10000000;
394         ts->tv_nsec = ((current_time.QuadPart - unix_epoch.QuadPart) %
395                        10000000) * 100;
396     } else {
397         return -1;
398     }
399 }
400 #endif /* _WIN32 */
401
402 void
403 xgettimeofday(struct timeval *tv)
404 {
405 #ifndef _WIN32
406     if (gettimeofday(tv, NULL) == -1) {
407         VLOG_FATAL("gettimeofday failed (%s)", ovs_strerror(errno));
408     }
409 #else
410     ULARGE_INTEGER current_time = xgetfiletime();
411
412     tv->tv_sec = (current_time.QuadPart - unix_epoch.QuadPart) / 10000000;
413     tv->tv_usec = ((current_time.QuadPart - unix_epoch.QuadPart) %
414                    10000000) / 10;
415 #endif
416 }
417
418 void
419 xclock_gettime(clock_t id, struct timespec *ts)
420 {
421     if (clock_gettime(id, ts) == -1) {
422         /* It seems like a bad idea to try to use vlog here because it is
423          * likely to try to check the current time. */
424         ovs_abort(errno, "xclock_gettime() failed");
425     }
426 }
427
428 /* Makes threads wait on timewarp_seq and be waken up when time is warped.
429  * This function will be no-op unless timeval_dummy_register() is called. */
430 void
431 timewarp_wait(void)
432 {
433     if (timewarp_enabled) {
434         uint64_t *last_seq = last_seq_get();
435
436         *last_seq = seq_read(timewarp_seq);
437         seq_wait(timewarp_seq, *last_seq);
438     }
439 }
440
441 static long long int
442 timeval_diff_msec(const struct timeval *a, const struct timeval *b)
443 {
444     return timeval_to_msec(a) - timeval_to_msec(b);
445 }
446
447 static void
448 timespec_add(struct timespec *sum,
449              const struct timespec *a,
450              const struct timespec *b)
451 {
452     struct timespec tmp;
453
454     tmp.tv_sec = a->tv_sec + b->tv_sec;
455     tmp.tv_nsec = a->tv_nsec + b->tv_nsec;
456     if (tmp.tv_nsec >= 1000 * 1000 * 1000) {
457         tmp.tv_nsec -= 1000 * 1000 * 1000;
458         tmp.tv_sec++;
459     }
460
461     *sum = tmp;
462 }
463
464 static bool
465 is_warped(const struct clock *c)
466 {
467     bool warped;
468
469     ovs_mutex_lock(&c->mutex);
470     warped = monotonic_clock.warp.tv_sec || monotonic_clock.warp.tv_nsec;
471     ovs_mutex_unlock(&c->mutex);
472
473     return warped;
474 }
475
476 static void
477 log_poll_interval(long long int last_wakeup)
478 {
479     long long int interval = time_msec() - last_wakeup;
480
481     if (interval >= 1000 && !is_warped(&monotonic_clock)) {
482         const struct rusage *last_rusage = get_recent_rusage();
483         struct rusage rusage;
484
485         getrusage(RUSAGE_SELF, &rusage);
486         VLOG_WARN("Unreasonably long %lldms poll interval"
487                   " (%lldms user, %lldms system)",
488                   interval,
489                   timeval_diff_msec(&rusage.ru_utime,
490                                     &last_rusage->ru_utime),
491                   timeval_diff_msec(&rusage.ru_stime,
492                                     &last_rusage->ru_stime));
493         if (rusage.ru_minflt > last_rusage->ru_minflt
494             || rusage.ru_majflt > last_rusage->ru_majflt) {
495             VLOG_WARN("faults: %ld minor, %ld major",
496                       rusage.ru_minflt - last_rusage->ru_minflt,
497                       rusage.ru_majflt - last_rusage->ru_majflt);
498         }
499         if (rusage.ru_inblock > last_rusage->ru_inblock
500             || rusage.ru_oublock > last_rusage->ru_oublock) {
501             VLOG_WARN("disk: %ld reads, %ld writes",
502                       rusage.ru_inblock - last_rusage->ru_inblock,
503                       rusage.ru_oublock - last_rusage->ru_oublock);
504         }
505         if (rusage.ru_nvcsw > last_rusage->ru_nvcsw
506             || rusage.ru_nivcsw > last_rusage->ru_nivcsw) {
507             VLOG_WARN("context switches: %ld voluntary, %ld involuntary",
508                       rusage.ru_nvcsw - last_rusage->ru_nvcsw,
509                       rusage.ru_nivcsw - last_rusage->ru_nivcsw);
510         }
511         coverage_log();
512     }
513 }
514 \f
515 /* CPU usage tracking. */
516
517 struct cpu_usage {
518     long long int when;         /* Time that this sample was taken. */
519     unsigned long long int cpu; /* Total user+system CPU usage when sampled. */
520 };
521
522 struct cpu_tracker {
523     struct cpu_usage older;
524     struct cpu_usage newer;
525     int cpu_usage;
526
527     struct rusage recent_rusage;
528 };
529 DEFINE_PER_THREAD_MALLOCED_DATA(struct cpu_tracker *, cpu_tracker_var);
530
531 static struct cpu_tracker *
532 get_cpu_tracker(void)
533 {
534     struct cpu_tracker *t = cpu_tracker_var_get();
535     if (!t) {
536         t = xzalloc(sizeof *t);
537         t->older.when = LLONG_MIN;
538         t->newer.when = LLONG_MIN;
539         cpu_tracker_var_set_unsafe(t);
540     }
541     return t;
542 }
543
544 static struct rusage *
545 get_recent_rusage(void)
546 {
547     return &get_cpu_tracker()->recent_rusage;
548 }
549
550 static int
551 getrusage_thread(struct rusage *rusage OVS_UNUSED)
552 {
553 #ifdef RUSAGE_THREAD
554     return getrusage(RUSAGE_THREAD, rusage);
555 #else
556     errno = EINVAL;
557     return -1;
558 #endif
559 }
560
561 static void
562 refresh_rusage(void)
563 {
564     struct cpu_tracker *t = get_cpu_tracker();
565     struct rusage *recent_rusage = &t->recent_rusage;
566
567     if (!getrusage_thread(recent_rusage)) {
568         long long int now = time_msec();
569         if (now >= t->newer.when + 3 * 1000) {
570             t->older = t->newer;
571             t->newer.when = now;
572             t->newer.cpu = (timeval_to_msec(&recent_rusage->ru_utime) +
573                             timeval_to_msec(&recent_rusage->ru_stime));
574
575             if (t->older.when != LLONG_MIN && t->newer.cpu > t->older.cpu) {
576                 unsigned int dividend = t->newer.cpu - t->older.cpu;
577                 unsigned int divisor = (t->newer.when - t->older.when) / 100;
578                 t->cpu_usage = divisor > 0 ? dividend / divisor : -1;
579             } else {
580                 t->cpu_usage = -1;
581             }
582         }
583     }
584 }
585
586 /* Returns an estimate of this process's CPU usage, as a percentage, over the
587  * past few seconds of wall-clock time.  Returns -1 if no estimate is available
588  * (which will happen if the process has not been running long enough to have
589  * an estimate, and can happen for other reasons as well). */
590 int
591 get_cpu_usage(void)
592 {
593     return get_cpu_tracker()->cpu_usage;
594 }
595 \f
596 /* Unixctl interface. */
597
598 /* "time/stop" stops the monotonic time returned by e.g. time_msec() from
599  * advancing, except due to later calls to "time/warp". */
600 static void
601 timeval_stop_cb(struct unixctl_conn *conn,
602                  int argc OVS_UNUSED, const char *argv[] OVS_UNUSED,
603                  void *aux OVS_UNUSED)
604 {
605     ovs_mutex_lock(&monotonic_clock.mutex);
606     atomic_store(&monotonic_clock.slow_path, true);
607     monotonic_clock.stopped = true;
608     xclock_gettime(monotonic_clock.id, &monotonic_clock.cache);
609     ovs_mutex_unlock(&monotonic_clock.mutex);
610
611     unixctl_command_reply(conn, NULL);
612 }
613
614 /* "time/warp MSECS" advances the current monotonic time by the specified
615  * number of milliseconds.  Unless "time/stop" has also been executed, the
616  * monotonic clock continues to tick forward at the normal rate afterward.
617  *
618  * Does not affect wall clock readings. */
619 static void
620 timeval_warp_cb(struct unixctl_conn *conn,
621                 int argc OVS_UNUSED, const char *argv[], void *aux OVS_UNUSED)
622 {
623     struct timespec ts;
624     int msecs;
625
626     msecs = atoi(argv[1]);
627     if (msecs <= 0) {
628         unixctl_command_reply_error(conn, "invalid MSECS");
629         return;
630     }
631
632     ts.tv_sec = msecs / 1000;
633     ts.tv_nsec = (msecs % 1000) * 1000 * 1000;
634
635     ovs_mutex_lock(&monotonic_clock.mutex);
636     atomic_store(&monotonic_clock.slow_path, true);
637     timespec_add(&monotonic_clock.warp, &monotonic_clock.warp, &ts);
638     ovs_mutex_unlock(&monotonic_clock.mutex);
639     seq_change(timewarp_seq);
640     /* give threads (eg. monitor) some chances to run */
641 #ifndef _WIN32
642     poll(NULL, 0, 10);
643 #else
644     Sleep(10);
645 #endif
646     unixctl_command_reply(conn, "warped");
647 }
648
649 void
650 timeval_dummy_register(void)
651 {
652     timewarp_enabled = true;
653     unixctl_command_register("time/stop", "", 0, 0, timeval_stop_cb, NULL);
654     unixctl_command_register("time/warp", "MSECS", 1, 1,
655                              timeval_warp_cb, NULL);
656 }
657
658
659
660 /* strftime() with an extension for high-resolution timestamps.  Any '#'s in
661  * 'format' will be replaced by subseconds, e.g. use "%S.###" to obtain results
662  * like "01.123".  */
663 size_t
664 strftime_msec(char *s, size_t max, const char *format,
665               const struct tm_msec *tm)
666 {
667     size_t n;
668
669     n = strftime(s, max, format, &tm->tm);
670     if (n) {
671         char decimals[4];
672         char *p;
673
674         sprintf(decimals, "%03d", tm->msec);
675         for (p = strchr(s, '#'); p; p = strchr(p, '#')) {
676             char *d = decimals;
677             while (*p == '#')  {
678                 *p++ = *d ? *d++ : '0';
679             }
680         }
681     }
682
683     return n;
684 }
685
686 struct tm_msec *
687 localtime_msec(long long int now, struct tm_msec *result)
688 {
689   time_t now_sec = now / 1000;
690   localtime_r(&now_sec, &result->tm);
691   result->msec = now % 1000;
692   return result;
693 }
694
695 struct tm_msec *
696 gmtime_msec(long long int now, struct tm_msec *result)
697 {
698   time_t now_sec = now / 1000;
699   gmtime_r(&now_sec, &result->tm);
700   result->msec = now % 1000;
701   return result;
702 }