poll-loop: Make wakeup logging more portable and easier to understand.

Until now, when the poll_loop module's log level was turned up to "debug",
it would log a backtrace of the call stack for the event that caused poll()
to wake up in poll_block().  This was pretty useful from time to time to
find out why ovs-vswitchd was using more CPU than expected, because we
could find out what was causing it to wake up.

But there were some issues.  One is simply that the backtrace was printed
as a series of hexadecimal numbers, so GDB or another debugger was needed
to translate it into human-readable format.  Compiler optimizations meant
that even the human-readable backtrace wasn't, in my experience, as helpful
as it could have been.  And, of course, one needed to have the binary to
interpret the backtrace.  When the backtrace couldn't be interpreted or
wasn't meaningful, there was essentially nothing to fall back on.

This commit changes the way that "debug" logging for poll_block() wakeups
works.  Instead of logging a backtrace, it logs the source code file name
and line number of the call to a poll_loop function, using __FILE__ and
__LINE__.  This is by itself much more meaningful than a sequence of
hexadecimal numbers, since no additional interpretation is necessary.  It
can be useful even if the Open vSwitch version is only approximately known.

In addition to the file and line, this commit adds, for wakeups caused by
file descriptors, information about the file descriptor itself: what kind
of file it is (regular file, directory, socket, etc.), the name of the file
(on Linux only), and the local and remote endpoints for socket file
descriptors.

Here are a few examples of the new output format:

932-ms timeout at ../ofproto/in-band.c:507
[POLLIN] on fd 20 (192.168.0.20:35388<->192.168.0.3:6633) at ../lib/stream-fd.c:149
[POLLIN] on fd 7 (FIFO pipe:[48049]) at ../lib/fatal-signal.c:168

1 files changed, 56 insertions, 44 deletions

diff --git a/lib/poll-loop.c b/lib/poll-loop.c
index e47cccc3..c944477d 100644
--- a/lib/poll-loop.c
+++ b/lib/poll-loop.c
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2008, 2009, 2010 Nicira Networks.
+ * Copyright (c) 2008, 2009, 2010, 2011 Nicira Networks.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -22,14 +22,19 @@
 #include <poll.h>
 #include <stdlib.h>
 #include <string.h>
-#include "backtrace.h"
 #include "coverage.h"
 #include "dynamic-string.h"
 #include "fatal-signal.h"
 #include "list.h"
+#include "socket-util.h"
 #include "timeval.h"
 #include "vlog.h"
 
+#undef poll_fd_wait
+#undef poll_timer_wait
+#undef poll_timer_wait_until
+#undef poll_immediate_wake
+
 VLOG_DEFINE_THIS_MODULE(poll_loop);
 
 COVERAGE_DEFINE(poll_fd_wait);
@@ -41,7 +46,7 @@ struct poll_waiter {
     struct list node;           /* Element in global waiters list. */
     int fd;                     /* File descriptor. */
     short int events;           /* Events to wait for (POLLIN, POLLOUT). */
-    struct backtrace *backtrace; /* Optionally, event that created waiter. */
+    const char *where;          /* Where the waiter was created. */
 
     /* Set only when poll_block() is called. */
     struct pollfd *pollfd;      /* Pointer to element of the pollfds array. */
@@ -57,10 +62,11 @@ static size_t n_waiters;
  * wait forever. */
 static int timeout = -1;
 
-/* Backtrace of 'timeout''s registration, if debugging is enabled. */
-static struct backtrace timeout_backtrace;
+/* Location where waiter created. */
+static const char *timeout_where;
 
-static struct poll_waiter *new_waiter(int fd, short int events);
+static struct poll_waiter *new_waiter(int fd, short int events,
+                                      const char *where);
 
 /* Registers 'fd' as waiting for the specified 'events' (which should be POLLIN
  * or POLLOUT or POLLIN | POLLOUT).  The following call to poll_block() will
@@ -68,23 +74,24 @@ static struct poll_waiter *new_waiter(int fd, short int events);
  *
  * The event registration is one-shot: only the following call to poll_block()
  * is affected.  The event will need to be re-registered after poll_block() is
- * called if it is to persist. */
+ * called if it is to persist.
+ *
+ * Ordinarily the 'where' argument is supplied automatically; see poll-loop.h
+ * for more information. */
 struct poll_waiter *
-poll_fd_wait(int fd, short int events)
+poll_fd_wait(int fd, short int events, const char *where)
 {
     COVERAGE_INC(poll_fd_wait);
-    return new_waiter(fd, events);
+    return new_waiter(fd, events, where);
 }
 
 /* The caller must ensure that 'msec' is not negative. */
 static void
-poll_timer_wait__(int msec)
+poll_timer_wait__(int msec, const char *where)
 {
     if (timeout < 0 || msec < timeout) {
         timeout = msec;
-        if (VLOG_IS_DBG_ENABLED()) {
-            backtrace_capture(&timeout_backtrace);
-        }
+        timeout_where = where;
     }
 }
 
@@ -94,13 +101,17 @@ poll_timer_wait__(int msec)
  *
  * The timer registration is one-shot: only the following call to poll_block()
  * is affected.  The timer will need to be re-registered after poll_block() is
- * called if it is to persist. */
+ * called if it is to persist.
+ *
+ * Ordinarily the 'where' argument is supplied automatically; see poll-loop.h
+ * for more information. */
 void
-poll_timer_wait(long long int msec)
+poll_timer_wait(long long int msec, const char *where)
 {
-    poll_timer_wait__(msec < 0 ? 0
-                      : msec > INT_MAX ? INT_MAX
-                      : msec);
+    poll_timer_wait__((msec < 0 ? 0
+                       : msec > INT_MAX ? INT_MAX
+                       : msec),
+                      where);
 }
 
 /* Causes the following call to poll_block() to wake up when the current time,
@@ -110,26 +121,33 @@ poll_timer_wait(long long int msec)
  *
  * The timer registration is one-shot: only the following call to poll_block()
  * is affected.  The timer will need to be re-registered after poll_block() is
- * called if it is to persist. */
+ * called if it is to persist.
+ *
+ * Ordinarily the 'where' argument is supplied automatically; see poll-loop.h
+ * for more information. */
 void
-poll_timer_wait_until(long long int msec)
+poll_timer_wait_until(long long int msec, const char *where)
 {
     long long int now = time_msec();
-    poll_timer_wait__(msec <= now ? 0
-                      : msec < now + INT_MAX ? msec - now
-                      : INT_MAX);
+    poll_timer_wait__((msec <= now ? 0
+                       : msec < now + INT_MAX ? msec - now
+                       : INT_MAX),
+                      where);
 }
 
 /* Causes the following call to poll_block() to wake up immediately, without
- * blocking. */
+ * blocking.
+ *
+ * Ordinarily the 'where' argument is supplied automatically; see poll-loop.h
+ * for more information. */
 void
-poll_immediate_wake(void)
+poll_immediate_wake(const char *where)
 {
-    poll_timer_wait(0);
+    poll_timer_wait(0, where);
 }
 
 static void PRINTF_FORMAT(2, 3)
-log_wakeup(const struct backtrace *backtrace, const char *format, ...)
+log_wakeup(const char *where, const char *format, ...)
 {
     struct ds ds;
     va_list args;
@@ -139,14 +157,10 @@ log_wakeup(const struct backtrace *backtrace, const char *format, ...)
     ds_put_format_valist(&ds, format, args);
     va_end(args);
 
-    if (backtrace) {
-        int i;
-
-        ds_put_char(&ds, ':');
-        for (i = 0; i < backtrace->n_frames; i++) {
-            ds_put_format(&ds, " 0x%"PRIxPTR, backtrace->frames[i]);
-        }
+    if (where) {
+        ds_put_format(&ds, " at %s", where);
     }
+
     VLOG_DBG("%s", ds_cstr(&ds));
     ds_destroy(&ds);
 }
@@ -190,24 +204,26 @@ poll_block(void)
         static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
         VLOG_ERR_RL(&rl, "poll: %s", strerror(-retval));
     } else if (!retval && VLOG_IS_DBG_ENABLED()) {
-        log_wakeup(&timeout_backtrace, "%d-ms timeout", timeout);
+        log_wakeup(timeout_where, "%d-ms timeout", timeout);
     }
 
     LIST_FOR_EACH_SAFE (pw, next, node, &waiters) {
         if (pw->pollfd->revents && VLOG_IS_DBG_ENABLED()) {
-            log_wakeup(pw->backtrace, "%s%s%s%s%s on fd %d",
+            char *description = describe_fd(pw->fd);
+            log_wakeup(pw->where, "%s%s%s%s%s on fd %d (%s)",
                        pw->pollfd->revents & POLLIN ? "[POLLIN]" : "",
                        pw->pollfd->revents & POLLOUT ? "[POLLOUT]" : "",
                        pw->pollfd->revents & POLLERR ? "[POLLERR]" : "",
                        pw->pollfd->revents & POLLHUP ? "[POLLHUP]" : "",
                        pw->pollfd->revents & POLLNVAL ? "[POLLNVAL]" : "",
-                       pw->fd);
+                       pw->fd, description);
+            free(description);
         }
         poll_cancel(pw);
     }
 
     timeout = -1;
-    timeout_backtrace.n_frames = 0;
+    timeout_where = NULL;
 
     /* Handle any pending signals before doing anything else. */
     fatal_signal_run();
@@ -224,7 +240,6 @@ poll_cancel(struct poll_waiter *pw)
 {
     if (pw) {
         list_remove(&pw->node);
-        free(pw->backtrace);
         free(pw);
         n_waiters--;
     }
@@ -232,16 +247,13 @@ poll_cancel(struct poll_waiter *pw)
 
 /* Creates and returns a new poll_waiter for 'fd' and 'events'. */
 static struct poll_waiter *
-new_waiter(int fd, short int events)
+new_waiter(int fd, short int events, const char *where)
 {
     struct poll_waiter *waiter = xzalloc(sizeof *waiter);
     assert(fd >= 0);
     waiter->fd = fd;
     waiter->events = events;
-    if (VLOG_IS_DBG_ENABLED()) {
-        waiter->backtrace = xmalloc(sizeof *waiter->backtrace);
-        backtrace_capture(waiter->backtrace);
-    }
+    waiter->where = where;
     list_push_back(&waiters, &waiter->node);
     n_waiters++;
     return waiter;