Add an option to log a stack trace any time the ioloop is blocked for

more than a specified amount of time.

tornado/ioloop.py

@@ -22,6 +22,12 @@
 import logging
 import select
 import time
+import traceback
+
+try:
+    import signal
+except ImportError:
+    signal = None
 
 try:
     import fcntl
@@ -96,6 +102,7 @@ def __init__(self, impl=None):
         self._timeouts = []
         self._running = False
         self._stopped = False
+        self._blocking_log_threshold = None
 
         # Create a pipe that we send bogus data to when we want to wake
         # the I/O loop when it is idle
@@ -154,6 +161,23 @@ def remove_handler(self, fd):
         except (OSError, IOError):
             logging.debug("Error deleting fd from IOLoop", exc_info=True)
 
+    def set_blocking_log_threshold(self, s):
+        """Logs a stack trace if the ioloop is blocked for more than s seconds.
+        Pass None to disable.  Requires python 2.6 on a unixy platform.
+        """
+        if not hasattr(signal, "setitimer"):
+            logging.error("set_blocking_log_threshold requires a signal module "
+                       "with the setitimer method")
+            return
+        self._blocking_log_threshold = s
+        if s is not None:
+            signal.signal(signal.SIGALRM, self._handle_alarm)
+
+    def _handle_alarm(self, signal, frame):
+        logging.warning('IOLoop blocked for %f seconds in\n%s',
+                     self._blocking_log_threshold,
+                     ''.join(traceback.format_stack(frame)))
+
     def start(self):
         """Starts the I/O loop.
 
@@ -192,6 +216,11 @@ def start(self):
             if not self._running:
                 break
 
+            if self._blocking_log_threshold is not None:
+                # clear alarm so it doesn't fire while poll is waiting for
+                # events.
+                signal.setitimer(signal.ITIMER_REAL, 0, 0)
+
             try:
                 event_pairs = self._impl.poll(poll_timeout)
             except Exception, e:
@@ -201,6 +230,10 @@ def start(self):
                 else:
                     raise
 
+            if self._blocking_log_threshold is not None:
+                signal.setitimer(signal.ITIMER_REAL,
+                                 self._blocking_log_threshold, 0)
+
             # Pop one fd at a time from the set of pending fds and run
             # its handler. Since that handler may perform actions on
             # other file descriptors, there may be reentrant calls to
@@ -224,6 +257,8 @@ def start(self):
                                   fd, exc_info=True)
         # reset the stopped flag so another start/stop pair can be issued
         self._stopped = False
+        if self._blocking_log_threshold is not None:
+            signal.setitimer(signal.ITIMER_REAL, 0, 0)
 
     def stop(self):
         """Stop the loop after the current event loop iteration is complete.