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)
commitf89ffb0e2f6fa8adc100192ea4b5f948170d8d57
treea95358d92f1ef01bf231e2f22fad99cd6c93afc5
parent0e6644c3880be9684f37f48da84907bb67112514
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
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