poll-loop: Make wakeup logging more portable and easier to understand.
authorBen Pfaff <blp@nicira.com>
Fri, 13 May 2011 20:06:49 +0000 (13:06 -0700)
committerBen Pfaff <blp@nicira.com>
Fri, 13 May 2011 21:38:15 +0000 (14:38 -0700)
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

lib/jsonrpc.c
lib/poll-loop.c
lib/poll-loop.h
lib/socket-util.c
lib/socket-util.h
lib/timer.c
lib/timer.h
lib/util.h

index afcc520..705cef7 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2009, 2010 Nicira Networks.
+ * Copyright (c) 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.
@@ -293,7 +293,7 @@ void
 jsonrpc_recv_wait(struct jsonrpc *rpc)
 {
     if (rpc->status || rpc->received || !byteq_is_empty(&rpc->input)) {
-        poll_immediate_wake();
+        (poll_immediate_wake)(rpc->name);
     } else {
         stream_recv_wait(rpc->stream);
     }
index e47cccc..c944477 100644 (file)
@@ -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.
 #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)
 \f
 /* 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;
index 65a2ff0..da8f6e2 100644 (file)
@@ -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.
@@ -28,6 +28,7 @@
 #define POLL_LOOP_H 1
 
 #include <poll.h>
+#include "util.h"
 
 #ifdef  __cplusplus
 extern "C" {
@@ -35,11 +36,28 @@ extern "C" {
 
 struct poll_waiter;
 
-/* Schedule events to wake up the following poll_block(). */
-struct poll_waiter *poll_fd_wait(int fd, short int events);
-void poll_timer_wait(long long int msec);
-void poll_timer_wait_until(long long int msec);
-void poll_immediate_wake(void);
+/* Schedule events to wake up the following poll_block().
+ *
+ * The poll_loop logs the 'where' argument to each function at "debug" level
+ * when an event causes a wakeup.  Ordinarily, it is automatically filled in
+ * with the location in the source of the call, and caller should therefore
+ * omit it.  But, if the function you are implementing is very generic, so that
+ * its location in the source would not be very helpful for debugging, you can
+ * avoid the macro expansion and pass a different argument, e.g.:
+ *      (poll_fd_wait)(fd, events, where);
+ * See timer_wait() for an example.
+ */
+struct poll_waiter *poll_fd_wait(int fd, short int events, const char *where);
+#define poll_fd_wait(fd, events) poll_fd_wait(fd, events, SOURCE_LOCATOR)
+
+void poll_timer_wait(long long int msec, const char *where);
+#define poll_timer_wait(msec) poll_timer_wait(msec, SOURCE_LOCATOR)
+
+void poll_timer_wait_until(long long int msec, const char *where);
+#define poll_timer_wait_until(msec) poll_timer_wait_until(msec, SOURCE_LOCATOR)
+
+void poll_immediate_wake(const char *where);
+#define poll_immediate_wake() poll_immediate_wake(SOURCE_LOCATOR)
 
 /* Wait until an event occurs. */
 void poll_block(void);
index 24e8f81..8ef63a7 100644 (file)
@@ -19,6 +19,7 @@
 #include <arpa/inet.h>
 #include <errno.h>
 #include <fcntl.h>
+#include <net/if.h>
 #include <netdb.h>
 #include <poll.h>
 #include <stddef.h>
 #include <sys/stat.h>
 #include <sys/un.h>
 #include <unistd.h>
+#include "dynamic-string.h"
 #include "fatal-signal.h"
+#include "packets.h"
 #include "util.h"
 #include "vlog.h"
+#if AF_PACKET && __linux__
+#include <linux/if_packet.h>
+#endif
+#ifdef HAVE_NETLINK
+#include "netlink-protocol.h"
+#include "netlink-socket.h"
+#endif
 
 VLOG_DEFINE_THIS_MODULE(socket_util);
 
@@ -784,3 +794,148 @@ xpipe(int fds[2])
         VLOG_FATAL("failed to create pipe (%s)", strerror(errno));
     }
 }
+
+static int
+getsockopt_int(int fd, int level, int optname, int *valuep)
+{
+    socklen_t len = sizeof *valuep;
+
+    return (getsockopt(fd, level, optname, valuep, &len) ? errno
+            : len == sizeof *valuep ? 0
+            : EINVAL);
+}
+
+static void
+describe_sockaddr(struct ds *string, int fd,
+                  int (*getaddr)(int, struct sockaddr *, socklen_t *))
+{
+    struct sockaddr_storage ss;
+    socklen_t len = sizeof ss;
+
+    if (!getaddr(fd, (struct sockaddr *) &ss, &len)) {
+        if (ss.ss_family == AF_INET) {
+            struct sockaddr_in sin;
+
+            memcpy(&sin, &ss, sizeof sin);
+            ds_put_format(string, IP_FMT":%"PRIu16,
+                          IP_ARGS(&sin.sin_addr.s_addr), ntohs(sin.sin_port));
+        } else if (ss.ss_family == AF_UNIX) {
+            struct sockaddr_un sun;
+            const char *null;
+            size_t maxlen;
+
+            memcpy(&sun, &ss, sizeof sun);
+            maxlen = len - offsetof(struct sockaddr_un, sun_path);
+            null = memchr(sun.sun_path, '\0', maxlen);
+            ds_put_buffer(string, sun.sun_path,
+                          null ? null - sun.sun_path : maxlen);
+        }
+#ifdef HAVE_NETLINK
+        else if (ss.ss_family == AF_NETLINK) {
+            int protocol;
+
+/* SO_PROTOCOL was introduced in 2.6.32.  Support it regardless of the version
+ * of the Linux kernel headers in use at build time. */
+#ifndef SO_PROTOCOL
+#define SO_PROTOCOL 38
+#endif
+
+            if (!getsockopt_int(fd, SOL_SOCKET, SO_PROTOCOL, &protocol)) {
+                switch (protocol) {
+                case NETLINK_ROUTE:
+                    ds_put_cstr(string, "NETLINK_ROUTE");
+                    break;
+
+                case NETLINK_GENERIC:
+                    ds_put_cstr(string, "NETLINK_GENERIC");
+                    break;
+
+                default:
+                    ds_put_format(string, "AF_NETLINK family %d", protocol);
+                    break;
+                }
+            } else {
+                ds_put_cstr(string, "AF_NETLINK");
+            }
+        }
+#endif
+#if AF_PACKET && __linux__
+        else if (ss.ss_family == AF_PACKET) {
+            struct sockaddr_ll sll;
+
+            memcpy(&sll, &ss, sizeof sll);
+            ds_put_cstr(string, "AF_PACKET");
+            if (sll.sll_ifindex) {
+                char name[IFNAMSIZ];
+
+                if (if_indextoname(sll.sll_ifindex, name)) {
+                    ds_put_format(string, "(%s)", name);
+                } else {
+                    ds_put_format(string, "(ifindex=%d)", sll.sll_ifindex);
+                }
+            }
+            if (sll.sll_protocol) {
+                ds_put_format(string, "(protocol=0x%"PRIu16")",
+                              ntohs(sll.sll_protocol));
+            }
+        }
+#endif
+        else if (ss.ss_family == AF_UNSPEC) {
+            ds_put_cstr(string, "AF_UNSPEC");
+        } else {
+            ds_put_format(string, "AF_%d", (int) ss.ss_family);
+        }
+    }
+}
+
+
+#ifdef __linux__
+static void
+put_fd_filename(struct ds *string, int fd)
+{
+    char buf[1024];
+    char *linkname;
+    int n;
+
+    linkname = xasprintf("/proc/self/fd/%d", fd);
+    n = readlink(linkname, buf, sizeof buf);
+    if (n > 0) {
+        ds_put_char(string, ' ');
+        ds_put_buffer(string, buf, n);
+        if (n > sizeof buf) {
+            ds_put_cstr(string, "...");
+        }
+    }
+    free(linkname);
+}
+#endif
+
+/* Returns a malloc()'d string describing 'fd', for use in logging. */
+char *
+describe_fd(int fd)
+{
+    struct ds string;
+    struct stat s;
+
+    ds_init(&string);
+    if (fstat(fd, &s)) {
+        ds_put_format(&string, "fstat failed (%s)", strerror(errno));
+    } else if (S_ISSOCK(s.st_mode)) {
+        describe_sockaddr(&string, fd, getsockname);
+        ds_put_cstr(&string, "<->");
+        describe_sockaddr(&string, fd, getpeername);
+    } else {
+        ds_put_cstr(&string, (isatty(fd) ? "tty"
+                              : S_ISDIR(s.st_mode) ? "directory"
+                              : S_ISCHR(s.st_mode) ? "character device"
+                              : S_ISBLK(s.st_mode) ? "block device"
+                              : S_ISREG(s.st_mode) ? "file"
+                              : S_ISFIFO(s.st_mode) ? "FIFO"
+                              : S_ISLNK(s.st_mode) ? "symbolic link"
+                              : "unknown"));
+#ifdef __linux__
+        put_fd_filename(&string, fd);
+#endif
+    }
+    return ds_steal_cstr(&string);
+}
index 8c5af39..8bc26bc 100644 (file)
@@ -50,4 +50,6 @@ int get_mtime(const char *file_name, struct timespec *mtime);
 
 void xpipe(int fds[2]);
 
+char *describe_fd(int fd);
+
 #endif /* socket-util.h */
index b640a7b..84d20a4 100644 (file)
@@ -34,9 +34,9 @@ timer_msecs_until_expired(const struct timer *timer)
 
 /* Causes poll_block() to wake when 'timer' expires. */
 void
-timer_wait(const struct timer *timer)
+(timer_wait)(const struct timer *timer, const char *where)
 {
     if (timer->t < LLONG_MAX) {
-        poll_timer_wait_until(timer->t);
+        (poll_timer_wait_until)(timer->t, where);
     }
 }
index d2bfd86..2197f93 100644 (file)
 #include <stdbool.h>
 
 #include "timeval.h"
+#include "util.h"
 
 struct timer {
     long long int t;
 };
 
 long long int timer_msecs_until_expired(const struct timer *);
-void timer_wait(const struct timer *);
+void timer_wait(const struct timer *, const char *where);
+#define timer_wait(timer) timer_wait(timer, SOURCE_LOCATOR)
 
 /* Causes 'timer' to expire when 'duration' milliseconds have passed.
  *
index 9c2352f..4ed291a 100644 (file)
@@ -77,6 +77,14 @@ extern const char *program_name;
 
 #define NOT_REACHED() abort()
 
+/* Expands to a string that looks like "<file>:<line>", e.g. "tmp.c:10".
+ *
+ * See http://c-faq.com/ansi/stringize.html for an explanation of STRINGIZE and
+ * STRINGIZE2. */
+#define SOURCE_LOCATOR __FILE__ ":" STRINGIZE(__LINE__)
+#define STRINGIZE(ARG) STRINGIZE2(ARG)
+#define STRINGIZE2(ARG) #ARG
+
 /* Given a pointer-typed lvalue OBJECT, expands to a pointer type that may be
  * assigned to OBJECT. */
 #ifdef __GNUC__