From f43e80e023378a2c1ef18d3caee9b76d6d2a6d23 Mon Sep 17 00:00:00 2001
From: Ethan Jackson <ethan@nicira.com>
Date: Mon, 22 Oct 2012 16:53:54 -0700
Subject: [PATCH] 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>
---
 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 516cf13d1..7e328bc24 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_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 b36203aaf..05f1c2d36 100644
--- 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 0f7d15c6c..5a7b6e25c 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);
 
-- 
2.43.0