[ovs-dev] [PATCH 3/3] poll-loop: Log backtraces when CPU usage is high.

[Ethan Jackson]

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 at nicira.com>
---
 lib/poll-loop.c |    6 ++++++
 lib/timeval.c   |   15 +++++++++++----
 lib/timeval.h   |    2 ++
 3 files changed, 19 insertions(+), 4 deletions(-)

diff --git a/lib/poll-loop.c b/lib/poll-loop.c
index 516cf13..23f0c22 100644
--- 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_cstr(&s, "\nBacktraces:\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 bd2a84d..b3245ca 100644
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -605,9 +605,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();
 
@@ -643,6 +646,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);
@@ -707,7 +714,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 0f7d15c..5a7b6e2 100644
--- 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);
 
-- 
1.7.9.5