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