Merge pull request #190 from adamcik/feature/dump-thread-tracebacks

Add a debug thread that dumps tracebacks

docs/changes.rst

@@ -88,6 +88,10 @@ backends:
 
 - Added support for search by filename to local backend.
 
+- Added optional background thread for debugging deadlocks. When the feature is
+  enabled via the ``--debug-thread`` or ``settings.DEBUG_THREAD`` a ``SIGUSR1``
+  signal will dump the traceback for all running threads.
+
 **Bug fixes**
 
 - :issue:`218`: The MPD commands ``listplaylist`` and ``listplaylistinfo`` now

docs/development.rst

@@ -284,6 +284,17 @@ Using this setup you can now run Mopidy with ``PROFILE=silent,spotify mopidy``
 if you for instance want to test Spotify without any actual audio output.
 
 
+Debugging deadlocks
+===================
+
+Between the numerous pykka threads and gstreamer interactions there can
+sometimes be a potential for deadlocks. In an effort to make these slightly
+simpler to debug ``settings.DEBUG_THREAD`` or ``--debug-thread``
+can be used to turn on an extra debug thread. This thread is not linked to
+the regular program flow, and it's only task is to dump traceback showing
+the other threads state when we get a ``SIGUSR1``.
+
+
 Writing documentation
 =====================
 

mopidy/__main__.py

@@ -41,8 +41,15 @@ logger = logging.getLogger('mopidy.main')
 
 def main():
     signal.signal(signal.SIGTERM, process.exit_handler)
+
     loop = gobject.MainLoop()
     options = parse_options()
+
+    if options.debug_thread or settings.DEBUG_THREAD:
+        debug_thread = process.DebugThread()
+        debug_thread.start()
+        signal.signal(signal.SIGUSR1, debug_thread.handler)
+
     try:
         log.setup_logging(options.verbosity_level, options.save_debug_log)
         check_old_folders()
@@ -99,6 +106,10 @@ def parse_options():
         '--list-deps',
         action='callback', callback=deps.list_deps_optparse_callback,
         help='list dependencies and their versions')
+    parser.add_option(
+        '--debug-thread',
+        action='store_true', dest='debug_thread',
+        help='run background thread that dumps tracebacks on SIGUSR1')
     return parser.parse_args(args=mopidy_args)[0]
 
 

mopidy/settings.py

@@ -45,6 +45,14 @@ DEBUG_LOG_FORMAT = u'%(levelname)-8s %(asctime)s' + \
 #:     DEBUG_LOG_FILENAME = u'mopidy.log'
 DEBUG_LOG_FILENAME = u'mopidy.log'
 
+#: If we should start a background thread that dumps thread's traceback when we
+#: get a SIGUSR1. Mainly a debug tool for figuring out deadlocks.
+#:
+#: Default::
+#: 
+#:     DEBUG_THREAD = False
+DEBUG_THREAD = False
+
 #: Location of the Mopidy .desktop file.
 #:
 #: Used by :mod:`mopidy.frontends.mpris`.

mopidy/utils/process.py

@@ -1,7 +1,9 @@
 import logging
 import signal
+import sys
 import thread
 import threading
+import traceback
 
 from pykka import ActorDeadError
 from pykka.registry import ActorRegistry
@@ -10,6 +12,8 @@ from mopidy import exceptions
 
 logger = logging.getLogger('mopidy.utils.process')
 
+SIGNALS = dict((k, v) for v, k in signal.__dict__.iteritems()
+    if v.startswith('SIG') and not v.startswith('SIG_'))
 
 def exit_process():
     logger.debug(u'Interrupting main...')
@@ -19,9 +23,7 @@ def exit_process():
 
 def exit_handler(signum, frame):
     """A :mod:`signal` handler which will exit the program on signal."""
-    signals = dict((k, v) for v, k in signal.__dict__.iteritems()
-                   if v.startswith('SIG') and not v.startswith('SIG_'))
-    logger.info(u'Got %s signal', signals[signum])
+    logger.info(u'Got %s signal', SIGNALS[signum])
     exit_process()
 
 
@@ -71,3 +73,27 @@ class BaseThread(threading.Thread):
 
     def run_inside_try(self):
         raise NotImplementedError
+
+class DebugThread(threading.Thread):
+    daemon = True
+    name = 'DebugThread'
+
+    event = threading.Event()
+
+    def handler(self, signum, frame):
+        logger.info(u'Got %s signal', SIGNALS[signum])
+        self.event.set()
+
+    def run(self):
+        while True:
+            self.event.wait()
+            threads = dict((t.ident, t.name) for t in threading.enumerate())
+
+            for ident, frame in sys._current_frames().items():
+                if self.ident != ident:
+                    stack = ''.join(traceback.format_stack(frame))
+                    logger.debug('Current state of %s (%s):\n%s',
+                        threads[ident], ident, stack)
+                del frame
+
+            self.event.clear()