coverage: Reimplement the "ovs-appctl coverage/show" command.

This commit changes the "ovs-appctl coverage/show" command to show the
the averaged per-second rates for the last few seconds, the last minute
and the last hour, and the total counts of all of the coverage counters.

Signed-off-by: Alex Wang <[email protected]>
Signed-off-by: Ethan Jackson <[email protected]>
Acked-by: Ethan Jackson <[email protected]>

lib/coverage-unixctl.man

@@ -8,4 +8,6 @@ main loop takes unusually long to run.
 Coverage counters are useful mainly for performance analysis and
 debugging.
 .IP "\fBcoverage/show\fR"
-Displays the values of all of the coverage counters.
+Displays the averaged per-second rates for the last few seconds, the
+last minute and the last hour, and the total counts of all of the
+coverage counters.

lib/coverage.c

@@ -63,7 +63,14 @@ struct coverage_counter *coverage_counters[] = {
 
 static struct ovs_mutex coverage_mutex = OVS_MUTEX_INITIALIZER;
 
+static long long int coverage_run_time = LLONG_MIN;
+
+/* Index counter used to compute the moving average array's index. */
+static unsigned int idx_count = 0;
+
 static void coverage_read(struct svec *);
+static unsigned int coverage_array_sum(const unsigned int *arr,
+                                       const unsigned int len);
 
 static void
 coverage_unixctl_show(struct unixctl_conn *conn, int argc OVS_UNUSED,
@@ -206,6 +213,7 @@ coverage_log(void)
 static void
 coverage_read(struct svec *lines)
 {
+    struct coverage_counter **c = coverage_counters;
     unsigned long long int *totals;
     size_t n_never_hit;
     uint32_t hash;
@@ -215,24 +223,37 @@ coverage_read(struct svec *lines)
 
     n_never_hit = 0;
     svec_add_nocopy(lines,
-                    xasprintf("Event coverage, hash=%08"PRIx32":", hash));
+                    xasprintf("Event coverage, avg rate over last: %d "
+                              "seconds, last minute, last hour,  "
+                              "hash=%08"PRIx32":",
+                              COVERAGE_RUN_INTERVAL/1000, hash));
 
     totals = xmalloc(n_coverage_counters * sizeof *totals);
     ovs_mutex_lock(&coverage_mutex);
     for (i = 0; i < n_coverage_counters; i++) {
-        totals[i] = coverage_counters[i]->total;
+        totals[i] = c[i]->total;
     }
     ovs_mutex_unlock(&coverage_mutex);
 
     for (i = 0; i < n_coverage_counters; i++) {
         if (totals[i]) {
-            svec_add_nocopy(lines, xasprintf("%-24s %9llu",
-                                             coverage_counters[i]->name,
-                                             totals[i]));
+            /* Shows the averaged per-second rates for the last
+             * COVERAGE_RUN_INTERVAL interval, the last minute and
+             * the last hour. */
+            svec_add_nocopy(lines,
+                xasprintf("%-24s %5.1f/sec %9.3f/sec "
+                          "%13.4f/sec   total: %llu",
+                          c[i]->name,
+                          (c[i]->min[(idx_count - 1) % MIN_AVG_LEN]
+                           * 1000.0 / COVERAGE_RUN_INTERVAL),
+                          coverage_array_sum(c[i]->min, MIN_AVG_LEN) / 60.0,
+                          coverage_array_sum(c[i]->hr,  HR_AVG_LEN) / 3600.0,
+                          totals[i]));
         } else {
             n_never_hit++;
         }
     }
+
     svec_add_nocopy(lines, xasprintf("%zu events never hit", n_never_hit));
     free(totals);
 }
@@ -249,3 +270,85 @@ coverage_clear(void)
     }
     ovs_mutex_unlock(&coverage_mutex);
 }
+
+/* Runs approximately every COVERAGE_RUN_INTERVAL amount of time to update the
+ * coverage counters' 'min' and 'hr' array.  'min' array is for cumulating
+ * per second counts into per minute count.  'hr' array is for cumulating per
+ * minute counts into per hour count.  Every thread may call this function. */
+void
+coverage_run(void)
+{
+    /* Defines the moving average array index variables. */
+    static unsigned int min_idx, hr_idx;
+    struct coverage_counter **c = coverage_counters;
+    long long int now;
+
+    ovs_mutex_lock(&coverage_mutex);
+    now = time_msec();
+    /* Initialize the coverage_run_time. */
+    if (coverage_run_time == LLONG_MIN) {
+        coverage_run_time = now + COVERAGE_RUN_INTERVAL;
+    }
+
+    if (now >= coverage_run_time) {
+        size_t i, j;
+        /* Computes the number of COVERAGE_RUN_INTERVAL slots, since
+         * it is possible that the actual run interval is multiple of
+         * COVERAGE_RUN_INTERVAL. */
+        int slots = (now - coverage_run_time) / COVERAGE_RUN_INTERVAL + 1;
+
+        for (i = 0; i < n_coverage_counters; i++) {
+            unsigned int count, portion;
+            unsigned int m_idx = min_idx;
+            unsigned int h_idx = hr_idx;
+            unsigned int idx = idx_count;
+
+            /* Computes the differences between the current total and the one
+             * recorded in last invocation of coverage_run(). */
+            count = c[i]->total - c[i]->last_total;
+            c[i]->last_total = c[i]->total;
+            /* The count over the time interval is evenly distributed
+             * among slots by calculating the portion. */
+            portion = count / slots;
+
+            for (j = 0; j < slots; j++) {
+                /* Updates the index variables. */
+                /* The m_idx is increased from 0 to MIN_AVG_LEN - 1. Every
+                 * time the m_idx finishes a cycle (a cycle is one minute),
+                 * the h_idx is incremented by 1. */
+                m_idx = idx % MIN_AVG_LEN;
+                h_idx = idx / MIN_AVG_LEN;
+
+                c[i]->min[m_idx] = portion + (j == (slots - 1)
+                                              ? count % slots : 0);
+                c[i]->hr[h_idx] = m_idx == 0
+                                  ? c[i]->min[m_idx]
+                                  : (c[i]->hr[h_idx] + c[i]->min[m_idx]);
+                /* This is to guarantee that h_idx ranges from 0 to 59. */
+                idx = (idx + 1) % (MIN_AVG_LEN * HR_AVG_LEN);
+            }
+        }
+
+        /* Updates the global index variables. */
+        idx_count = (idx_count + slots) % (MIN_AVG_LEN * HR_AVG_LEN);
+        min_idx = idx_count % MIN_AVG_LEN;
+        hr_idx  = idx_count / MIN_AVG_LEN;
+        /* Updates the run time. */
+        coverage_run_time = now + COVERAGE_RUN_INTERVAL;
+    }
+    ovs_mutex_unlock(&coverage_mutex);
+}
+
+static unsigned int
+coverage_array_sum(const unsigned int *arr, const unsigned int len)
+{
+    unsigned int sum = 0;
+    size_t i;
+
+    ovs_mutex_lock(&coverage_mutex);
+    for (i = 0; i < len; i++) {
+        sum += arr[i];
+    }
+    ovs_mutex_unlock(&coverage_mutex);
+    return sum;
+}

lib/coverage.h

@@ -30,11 +30,25 @@
 #include "ovs-thread.h"
 #include "vlog.h"
 
+/* Makes coverage_run run every 5000 ms (5 seconds).
+ * If this value is redefined, the new value must
+ * divide 60000 (1 minute). */
+#define COVERAGE_RUN_INTERVAL    5000
+BUILD_ASSERT_DECL(60000 % COVERAGE_RUN_INTERVAL == 0);
+
+/* Defines the moving average array length. */
+#define MIN_AVG_LEN (60000/COVERAGE_RUN_INTERVAL)
+#define HR_AVG_LEN  60
+
 /* A coverage counter. */
 struct coverage_counter {
     const char *const name;            /* Textual name. */
     unsigned int (*const count)(void); /* Gets, zeros this thread's count. */
     unsigned long long int total;      /* Total count. */
+    unsigned long long int last_total;
+    /* The moving average arrays. */
+    unsigned int min[MIN_AVG_LEN];
+    unsigned int hr[HR_AVG_LEN];
 };
 
 /* Defines COUNTER.  There must be exactly one such definition at file scope
@@ -56,7 +70,7 @@ struct coverage_counter {
         }                                                               \
         extern struct coverage_counter counter_##COUNTER;               \
         struct coverage_counter counter_##COUNTER                       \
-            = { #COUNTER, COUNTER##_count, 0 };                         \
+            = { #COUNTER, COUNTER##_count, 0, 0, {0}, {0} };            \
         extern struct coverage_counter *counter_ptr_##COUNTER;          \
         struct coverage_counter *counter_ptr_##COUNTER                  \
             __attribute__((section("coverage"))) = &counter_##COUNTER
@@ -80,6 +94,7 @@ struct coverage_counter {
 void coverage_init(void);
 void coverage_log(void);
 void coverage_clear(void);
+void coverage_run(void);
 
 /* Implementation detail. */
 #define COVERAGE_DEFINE__(COUNTER)                              \

lib/timeval.c

@@ -234,6 +234,7 @@ time_poll(struct pollfd *pollfds, int n_pollfds, long long int timeout_when,
         log_poll_interval(*last_wakeup);
     }
     coverage_clear();
+    coverage_run();
     start = time_msec();
 
     timeout_when = MIN(timeout_when, deadline);

tests/ofproto-dpif.at

@@ -2838,3 +2838,37 @@ AT_CHECK([ovs-appctl bond/show | sed -n '/^.*may_enable:.*/p'], [0], [dnl
 
 OVS_VSWITCHD_STOP
 AT_CLEANUP
+
+# Unit test for appctl coverage/show command
+AT_SETUP([ofproto-dpif - coverage/show])
+OVS_VSWITCHD_START
+
+ovs-appctl time/stop
+# before the first 5 seconds, nothing can be calculated but the total count.
+# there should be two unixctl commands received, but the count of the "appctl
+# coverage/show" command is not updated to the total. so there show only 1.
+AT_CHECK([ovs-appctl coverage/show | sed -n '/^unixctl_received.*/p'], [], [dnl
+unixctl_received           0.0/sec     0.000/sec        0.0000/sec   total: 1
+])
+
+ovs-appctl time/warp 5000
+# at first 5 second time instant, should have stats.
+AT_CHECK([ovs-appctl coverage/show | sed -n '/^unixctl_received.*/p'], [], [dnl
+unixctl_received           0.6/sec     0.050/sec        0.0008/sec   total: 3
+])
+
+for i in `seq 0 10`; do ovs-appctl time/warp 5000; done
+# advance to first 1 minute time instant.
+AT_CHECK([ovs-appctl coverage/show | sed -n '/^unixctl_received.*/p'], [], [dnl
+unixctl_received           0.2/sec     0.250/sec        0.0042/sec   total: 15
+])
+
+ovs-appctl time/warp 60000
+# advance to next 1 minute time instant directly, should observe the per-minute
+# rate drop.
+AT_CHECK([ovs-appctl coverage/show | sed -n '/^unixctl_received.*/p'], [], [dnl
+unixctl_received           0.4/sec     0.033/sec        0.0047/sec   total: 17
+])
+
+OVS_VSWITCHD_STOP
+AT_CLEANUP