From 98cf638b19c2a5deca603fd4ed90e3b0cbfc7b7e Mon Sep 17 00:00:00 2001 From: Alex Wang Date: Mon, 30 Sep 2013 18:31:44 -0700 Subject: [PATCH] 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 Signed-off-by: Ethan Jackson Acked-by: Ethan Jackson --- lib/coverage-unixctl.man | 4 +- lib/coverage.c | 113 +++++++++++++++++++++++++++++++++++++-- lib/coverage.h | 17 +++++- lib/timeval.c | 1 + tests/ofproto-dpif.at | 34 ++++++++++++ 5 files changed, 162 insertions(+), 7 deletions(-) diff --git a/lib/coverage-unixctl.man b/lib/coverage-unixctl.man index 971889419..8e5df818e 100644 --- a/lib/coverage-unixctl.man +++ b/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. diff --git a/lib/coverage.c b/lib/coverage.c index 23e29973d..43647344b 100644 --- a/lib/coverage.c +++ b/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; +} diff --git a/lib/coverage.h b/lib/coverage.h index 3d1a115d4..163728eba 100644 --- a/lib/coverage.h +++ b/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) \ diff --git a/lib/timeval.c b/lib/timeval.c index 223ed3084..64ae845a1 100644 --- a/lib/timeval.c +++ b/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); diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at index 652304ef6..a5625518d 100644 --- a/tests/ofproto-dpif.at +++ b/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 -- 2.39.5