[ovs-dev] [coverage 3/3] coverage: Make ovs-appctl command more useful and less alarming.
Ben Pfaff
blp at nicira.com
Thu Apr 26 21:08:51 UTC 2012
Thanks, I'll push this series soon.
On Wed, Apr 25, 2012 at 07:04:16PM -0700, Ethan Jackson wrote:
> Looks good, thanks.
>
> Ethan
>
> On Fri, Apr 20, 2012 at 14:10, Ben Pfaff <blp at nicira.com> wrote:
> > I've had a few complaints that ovs-vswitchd logs its coverage counters
> > at WARN level, but this is mainly wrong: ovs-vswitchd only logs coverage
> > counters at WARN level when the "coverage/log" command is used through
> > ovs-appctl. This was even documented.
> >
> > The reason to log at such a high level was to make it fairly certain that
> > these messages specifically requested by the admin would not be filtered
> > out before making it to the log. But it's even better if the admin just
> > gets the coverage counters as a reply to the ovs-appctl command. So that
> > is what this commit does.
> >
> > This commit also improves the documentation of the ovs-appctl command.
> >
> > Signed-off-by: Ben Pfaff <blp at nicira.com>
> > ---
> > NEWS | 3 +
> > lib/automake.mk | 1 +
> > lib/coverage-unixctl.man | 11 +++++
> > lib/coverage.c | 91 ++++++++++++++++++++++++++++----------------
> > lib/coverage.h | 4 +-
> > lib/timeval.c | 6 +--
> > manpages.mk | 2 +
> > ovsdb/ovsdb-server.1.in | 1 +
> > vswitchd/ovs-vswitchd.8.in | 2 -
> > 9 files changed, 79 insertions(+), 42 deletions(-)
> > create mode 100644 lib/coverage-unixctl.man
> >
> > diff --git a/NEWS b/NEWS
> > index 9c73352..e717a4a 100644
> > --- a/NEWS
> > +++ b/NEWS
> > @@ -12,6 +12,9 @@ post-v1.6.0
> > - Added support for spawning ovs-test server from the client.
> > - Now ovs-test is able to automatically create test bridges and ports.
> > - "ovs-dpctl dump-flows" now prints observed TCP flags in TCP flows.
> > + - The "coverage/log" command previously available through ovs-appctl
> > + has been replaced by "coverage/show". The new command replies with
> > + coverage counter values, instead of logging them.
> >
> >
> > v1.6.0 - xx xxx xxxx
> > diff --git a/lib/automake.mk b/lib/automake.mk
> > index 5ce287f..2d2617e 100644
> > --- a/lib/automake.mk
> > +++ b/lib/automake.mk
> > @@ -253,6 +253,7 @@ EXTRA_DIST += \
> > MAN_FRAGMENTS += \
> > lib/common.man \
> > lib/common-syn.man \
> > + lib/coverage-unixctl.man \
> > lib/daemon.man \
> > lib/daemon-syn.man \
> > lib/leak-checker.man \
> > diff --git a/lib/coverage-unixctl.man b/lib/coverage-unixctl.man
> > new file mode 100644
> > index 0000000..9718894
> > --- /dev/null
> > +++ b/lib/coverage-unixctl.man
> > @@ -0,0 +1,11 @@
> > +.SS "COVERAGE COMMANDS"
> > +These commands manage \fB\*(PN\fR's ``coverage counters,'' which count
> > +the number of times particular events occur during a daemon's runtime.
> > +In addition to these commands, \fB\*(PN\fR automatically logs coverage
> > +counter values, at \fBINFO\fR level, when it detects that the daemon's
> > +main loop takes unusually long to run.
> > +.PP
> > +Coverage counters are useful mainly for performance analysis and
> > +debugging.
> > +.IP "\fBcoverage/show\fR"
> > +Displays the values of all of the coverage counters.
> > diff --git a/lib/coverage.c b/lib/coverage.c
> > index ff20f5e..ee27af0 100644
> > --- a/lib/coverage.c
> > +++ b/lib/coverage.c
> > @@ -20,6 +20,7 @@
> > #include <stdlib.h>
> > #include "dynamic-string.h"
> > #include "hash.h"
> > +#include "svec.h"
> > #include "timeval.h"
> > #include "unixctl.h"
> > #include "util.h"
> > @@ -48,19 +49,28 @@ struct coverage_counter *coverage_counters[] = {
> >
> > static unsigned int epoch;
> >
> > +static void coverage_read(struct svec *);
> > +
> > static void
> > -coverage_unixctl_log(struct unixctl_conn *conn, int argc OVS_UNUSED,
> > +coverage_unixctl_show(struct unixctl_conn *conn, int argc OVS_UNUSED,
> > const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED)
> > {
> > - coverage_log(VLL_WARN, false);
> > - unixctl_command_reply(conn, NULL);
> > + struct svec lines;
> > + char *reply;
> > +
> > + svec_init(&lines);
> > + coverage_read(&lines);
> > + reply = svec_join(&lines, "\n", "\n");
> > + unixctl_command_reply(conn, reply);
> > + free(reply);
> > + svec_destroy(&lines);
> > }
> >
> > void
> > coverage_init(void)
> > {
> > - unixctl_command_register("coverage/log", "", 0, 0,
> > - coverage_unixctl_log, NULL);
> > + unixctl_command_register("coverage/show", "", 0, 0,
> > + coverage_unixctl_show, NULL);
> > }
> >
> > /* Sorts coverage counters in descending order by count, within equal counts
> > @@ -144,60 +154,75 @@ coverage_hit(uint32_t hash)
> > }
> > }
> >
> > +/* Logs the coverage counters, unless a similar set of events has already been
> > + * logged.
> > + *
> > + * This function logs at log level VLL_INFO. Use care before adjusting this
> > + * level, because depending on its configuration, syslogd can write changes
> > + * synchronously, which can cause the coverage messages to take several seconds
> > + * to write. */
> > +void
> > +coverage_log(void)
> > +{
> > + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 3);
> > +
> > + if (!VLOG_DROP_INFO(&rl)) {
> > + uint32_t hash = coverage_hash();
> > + if (coverage_hit(hash)) {
> > + VLOG_INFO("Skipping details of duplicate event coverage for "
> > + "hash=%08"PRIx32" in epoch %u", hash, epoch);
> > + } else {
> > + struct svec lines;
> > + const char *line;
> > + size_t i;
> > +
> > + svec_init(&lines);
> > + coverage_read(&lines);
> > + SVEC_FOR_EACH (i, line, &lines) {
> > + VLOG_INFO("%s", line);
> > + }
> > + svec_destroy(&lines);
> > + }
> > + }
> > +}
> > +
> > static void
> > -coverage_log_counter(enum vlog_level level, const struct coverage_counter *c)
> > +coverage_read_counter(struct svec *lines, const struct coverage_counter *c)
> > {
> > - VLOG(level, "%-24s %5u / %9llu", c->name, c->count, c->count + c->total);
> > + svec_add_nocopy(lines, xasprintf("%-24s %5u / %9llu",
> > + c->name, c->count, c->count + c->total));
> > }
> >
> > -/* Logs the coverage counters at the given vlog 'level'. If
> > - * 'suppress_dups' is true, then duplicate events are not displayed.
> > - * Care should be taken in the value used for 'level'. Depending on the
> > - * configuration, syslog can write changes synchronously, which can
> > - * cause the coverage messages to take several seconds to write. */
> > -void
> > -coverage_log(enum vlog_level level, bool suppress_dups)
> > +/* Adds coverage counter information to 'lines'. */
> > +static void
> > +coverage_read(struct svec *lines)
> > {
> > - static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 3);
> > size_t n_never_hit;
> > uint32_t hash;
> > size_t i;
> >
> > - if (suppress_dups
> > - ? !vlog_is_enabled(THIS_MODULE, level)
> > - : vlog_should_drop(THIS_MODULE, level, &rl)) {
> > - return;
> > - }
> > -
> > hash = coverage_hash();
> > - if (suppress_dups) {
> > - if (coverage_hit(hash)) {
> > - VLOG(level, "Skipping details of duplicate event coverage for "
> > - "hash=%08"PRIx32" in epoch %u", hash, epoch);
> > - return;
> > - }
> > - }
> >
> > n_never_hit = 0;
> > - VLOG(level, "Event coverage (epoch %u/entire run), hash=%08"PRIx32":",
> > - epoch, hash);
> > + svec_add_nocopy(lines, xasprintf("Event coverage (epoch %u/entire run), "
> > + "hash=%08"PRIx32":", epoch, hash));
> > for (i = 0; i < n_coverage_counters; i++) {
> > struct coverage_counter *c = coverage_counters[i];
> > if (c->count) {
> > - coverage_log_counter(level, c);
> > + coverage_read_counter(lines, c);
> > }
> > }
> > for (i = 0; i < n_coverage_counters; i++) {
> > struct coverage_counter *c = coverage_counters[i];
> > if (!c->count) {
> > if (c->total) {
> > - coverage_log_counter(level, c);
> > + coverage_read_counter(lines, c);
> > } else {
> > n_never_hit++;
> > }
> > }
> > }
> > - VLOG(level, "%zu events never hit", n_never_hit);
> > + svec_add_nocopy(lines, xasprintf("%zu events never hit", n_never_hit));
> > }
> >
> > /* Advances to the next epoch of coverage, resetting all the counters to 0. */
> > diff --git a/lib/coverage.h b/lib/coverage.h
> > index b7db6c4..0f389bf 100644
> > --- a/lib/coverage.h
> > +++ b/lib/coverage.h
> > @@ -1,5 +1,5 @@
> > /*
> > - * Copyright (c) 2009, 2010, 2011 Nicira Networks.
> > + * Copyright (c) 2009, 2010, 2011, 2012 Nicira Networks.
> > *
> > * Licensed under the Apache License, Version 2.0 (the "License");
> > * you may not use this file except in compliance with the License.
> > @@ -56,7 +56,7 @@ struct coverage_counter {
> > #define COVERAGE_ADD(COUNTER, AMOUNT) counter_##COUNTER.count += (AMOUNT);
> >
> > void coverage_init(void);
> > -void coverage_log(enum vlog_level, bool suppress_dups);
> > +void coverage_log(void);
> > void coverage_clear(void);
> >
> > /* Implementation detail. */
> > diff --git a/lib/timeval.c b/lib/timeval.c
> > index 9829100..b60ece9 100644
> > --- a/lib/timeval.c
> > +++ b/lib/timeval.c
> > @@ -499,11 +499,7 @@ log_poll_interval(long long int last_wakeup)
> > rusage.ru_nivcsw - last_rusage->ru_nivcsw);
> > }
> > }
> > - /* Care should be taken in the value chosen for logging. Depending
> > - * on the configuration, syslog can write changes synchronously,
> > - * which can cause the coverage messages to take longer to log
> > - * than the processing delay that triggered it. */
> > - coverage_log(VLL_INFO, true);
> > + coverage_log();
> > }
> >
> > /* Update exponentially weighted moving average. With these parameters, a
> > diff --git a/manpages.mk b/manpages.mk
> > index 14bb41f..1773263 100644
> > --- a/manpages.mk
> > +++ b/manpages.mk
> > @@ -34,6 +34,7 @@ ovsdb/ovsdb-server.1: \
> > ovsdb/ovsdb-server.1.in \
> > lib/common-syn.man \
> > lib/common.man \
> > + lib/coverage-unixctl.man \
> > lib/daemon-syn.man \
> > lib/daemon.man \
> > lib/ssl-bootstrap-syn.man \
> > @@ -51,6 +52,7 @@ ovsdb/ovsdb-server.1: \
> > ovsdb/ovsdb-server.1.in:
> > lib/common-syn.man:
> > lib/common.man:
> > +lib/coverage-unixctl.man:
> > lib/daemon-syn.man:
> > lib/daemon.man:
> > lib/ssl-bootstrap-syn.man:
> > diff --git a/ovsdb/ovsdb-server.1.in b/ovsdb/ovsdb-server.1.in
> > index 9e2d79a..dfe9208 100644
> > --- a/ovsdb/ovsdb-server.1.in
> > +++ b/ovsdb/ovsdb-server.1.in
> > @@ -123,6 +123,7 @@ This command might be useful for debugging issues with database
> > clients.
> > .
> > .so lib/vlog-unixctl.man
> > +.so lib/coverage-unixctl.man
> > .so lib/stress-unixctl.man
> > .SH "SEE ALSO"
> > .
> > diff --git a/vswitchd/ovs-vswitchd.8.in b/vswitchd/ovs-vswitchd.8.in
> > index 1abae6f..6c9f3e4 100644
> > --- a/vswitchd/ovs-vswitchd.8.in
> > +++ b/vswitchd/ovs-vswitchd.8.in
> > @@ -108,8 +108,6 @@ how to configure Open vSwitch.
> > .SS "GENERAL COMMANDS"
> > .IP "\fBexit\fR"
> > Causes \fBovs\-vswitchd\fR to gracefully terminate.
> > -.IP "\fBcoverage/log\fR"
> > -Logs coverage counters at level warn.
> > .IP "\fBqos/show\fR \fIinterface\fR"
> > Queries the kernel for Quality of Service configuration and statistics
> > associated with the given \fIinterface\fR.
> > --
> > 1.7.2.5
> >
> > _______________________________________________
> > dev mailing list
> > dev at openvswitch.org
> > http://openvswitch.org/mailman/listinfo/dev
More information about the dev
mailing list