poll-loop: Log backtraces when CPU usage is high.

Often when debugging Open vSwitch, one will see in the logs that
CPU usage has been high for some period of time, but it's totally
unclear why.  In an attempt to remedy the situation, this patch
logs backtraces taken at regular intervals as a poor man's
profiling alternative.

Signed-off-by: Ethan Jackson <ethan@nicira.com>

diff --git a/lib/poll-loop.c b/lib/poll-loop.c
index 516cf13d1db321925a80c71dfd63de6bfd1de646..7e328bc24ce486b2243cdfce1929c5464f513b02 100644 (file)
--- a/lib/poll-loop.c
+++ b/lib/poll-loop.c
@@ -157,6 +157,7 @@ poll_immediate_wake(const char *where)
 static void
 log_wakeup(const char *where, const struct pollfd *pollfd, int timeout)
 {
+    static struct vlog_rate_limit trace_rl = VLOG_RATE_LIMIT_INIT(1, 1);
     static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(10, 10);
     enum vlog_level level;
     int cpu_usage;
@@ -200,6 +201,11 @@ log_wakeup(const char *where, const struct pollfd *pollfd, int timeout)
     }
     if (cpu_usage >= 0) {
         ds_put_format(&s, " (%d%% CPU usage)", cpu_usage);
+
+        if (!vlog_should_drop(THIS_MODULE, level, &trace_rl)) {
+            ds_put_char(&s, '\n');
+            format_backtraces(&s, 2);
+        }
     }
     VLOG(level, "%s", ds_cstr(&s));
     ds_destroy(&s);

diff --git a/lib/timeval.c b/lib/timeval.c
index b36203aaf050389eab6e6d389703b8eaeb3588e6..05f1c2d3643030dc16c20bdcacb44cc0f72311ac 100644 (file)
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -615,9 +615,12 @@ trace_map_lookup(struct hmap *trace_map, struct trace *key)
     return NULL;
 }
 
-
-static void
-format_backtraces(struct ds *ds)
+/*  Appends a string to 'ds' representing backtraces recorded at regular
+ *  intervals in the recent past.  This information can be used to get a sense
+ *  of what the process has been spending the majority of time doing.  Will
+ *  ommit any backtraces which have not occurred at least 'min_count' times. */
+void
+format_backtraces(struct ds *ds, size_t min_count)
 {
     time_init();
 
@@ -652,6 +655,10 @@ format_backtraces(struct ds *ds)
 
             hmap_remove(&trace_map, &trace->node);
 
+            if (trace->count < min_count) {
+                continue;
+            }
+
             frame_strs = backtrace_symbols(trace->backtrace, trace->n_frames);
 
             ds_put_format(ds, "Count %zu\n", trace->count);
@@ -715,7 +722,7 @@ backtrace_cb(struct unixctl_conn *conn,
     struct ds ds = DS_EMPTY_INITIALIZER;
 
     assert(HAVE_EXECINFO_H && CACHE_TIME);
-    format_backtraces(&ds);
+    format_backtraces(&ds, 0);
     unixctl_command_reply(conn, ds_cstr(&ds));
     ds_destroy(&ds);
 }

diff --git a/lib/timeval.h b/lib/timeval.h
index 0f7d15c6c7ba5901a85438b118a4b34ef0d99deb..5a7b6e25c62aeabc09b3b1089913446a828a8576 100644 (file)
--- a/lib/timeval.h
+++ b/lib/timeval.h
@@ -25,6 +25,7 @@
 extern "C" {
 #endif
 
+struct ds;
 struct pollfd;
 struct timespec;
 struct timeval;
@@ -83,6 +84,7 @@ long long int timeval_to_msec(const struct timeval *);
 void xgettimeofday(struct timeval *);
 
 int get_cpu_usage(void);
+void format_backtraces(struct ds *, size_t min_count);
 
 long long int time_boot_msec(void);