Log a warning when the interval between poll_block() calls is excessive.

diff --git a/lib/timeval.c b/lib/timeval.c
index 327a8cdeb677136514840a248fcc56116d1eec08..00cf0551d7d54a11695408b1ad96fcac0299f637 100644 (file)
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -42,6 +42,9 @@
 #include "fatal-signal.h"
 #include "util.h"
 
+#include "vlog.h"
+#define THIS_MODULE VLM_timeval
+
 /* Initialized? */
 static bool inited;
 
@@ -59,6 +62,7 @@ static void refresh_if_ticked(void);
 static time_t time_add(time_t, time_t);
 static void block_sigalrm(sigset_t *);
 static void unblock_sigalrm(const sigset_t *);
+static void log_poll_interval(long long int last_wakeup);
 
 /* Initializes the timetracking module. */
 void
@@ -154,12 +158,14 @@ time_alarm(unsigned int secs)
 int
 time_poll(struct pollfd *pollfds, int n_pollfds, int timeout)
 {
+    static long long int last_wakeup;
     long long int start;
     sigset_t oldsigs;
     bool blocked;
     int retval;
 
     time_refresh();
+    log_poll_interval(last_wakeup);
     start = time_msec();
     blocked = false;
     for (;;) {
@@ -188,6 +194,7 @@ time_poll(struct pollfd *pollfds, int n_pollfds, int timeout)
     if (blocked) {
         unblock_sigalrm(&oldsigs);
     }
+    last_wakeup = time_msec();
     return retval;
 }
 
@@ -236,3 +243,34 @@ unblock_sigalrm(const sigset_t *oldsigs)
         ofp_fatal(errno, "sigprocmask");
     }
 }
+
+static void
+log_poll_interval(long long int last_wakeup)
+{
+    static unsigned int mean_interval; /* In 16ths of a millisecond. */
+    static unsigned int n_samples;
+
+    long long int now;
+    unsigned int interval;      /* In 16ths of a millisecond. */
+
+    /* Compute interval from last wakeup to now in 16ths of a millisecond,
+     * capped at 10 seconds (16000 in this unit). */
+    now = time_msec();
+    interval = MIN(10000, now - last_wakeup) << 4;
+
+    /* Warn if we took too much time between polls. */
+    if (n_samples > 10 && interval > mean_interval * 8) {
+        VLOG_WARN("%u ms poll interval is over %u times "
+                  "the weighted mean interval %u ms (%u samples)",
+                  (interval + 8) / 16, interval / mean_interval,
+                  (mean_interval + 8) / 16, n_samples);
+    }
+
+    /* Update exponentially weighted moving average.  With these parameters, a
+     * given value decays to 1% of its value in about 100 time steps.  */
+    if (n_samples++) {
+        mean_interval = (mean_interval * 122 + interval * 6 + 64) / 128;
+    } else {
+        mean_interval = interval;
+    }
+}

diff --git a/lib/vlog-modules.def b/lib/vlog-modules.def
index 778f1c7a9b76b14650f05dd80708eb838b5e5f41..f79fe2b5907f9b7b94c2ac3299ba9e8b2f1e9577 100644 (file)
--- a/lib/vlog-modules.def
+++ b/lib/vlog-modules.def
@@ -43,6 +43,7 @@ VLOG_MODULE(status)
 VLOG_MODULE(svec)
 VLOG_MODULE(switch)
 VLOG_MODULE(terminal)
+VLOG_MODULE(timeval)
 VLOG_MODULE(socket_util)
 VLOG_MODULE(vconn_tcp)
 VLOG_MODULE(vconn_ssl)