From 88f0ffb9f2b01b9d32c6f7a2d06a4987249d805b Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Sun, 9 Sep 2012 22:48:08 +0200 Subject: [PATCH 1/5] Add a debug thread that dumps tracebacks. Start and extra thread that blocks on a threading event until SIGUSR1 is received. Then dump the tracebacks for all threads except itself. This is only really useful as a debug tool for deadlocks, so we might want to hide it behind a flag? --- mopidy/__main__.py | 7 ++++++- mopidy/utils/process.py | 31 +++++++++++++++++++++++++++++-- 2 files changed, 35 insertions(+), 3 deletions(-) diff --git a/mopidy/__main__.py b/mopidy/__main__.py index 9bee390e..64465c19 100644 --- a/mopidy/__main__.py +++ b/mopidy/__main__.py @@ -36,7 +36,7 @@ from mopidy.utils.deps import list_deps_optparse_callback from mopidy.utils.log import setup_logging from mopidy.utils.path import get_or_create_folder, get_or_create_file from mopidy.utils.process import (exit_handler, stop_remaining_actors, - stop_actors_by_class) + stop_actors_by_class, DebugThread) from mopidy.utils.settings import list_settings_optparse_callback @@ -44,7 +44,12 @@ logger = logging.getLogger('mopidy.main') def main(): + debug_thread = DebugThread() + debug_thread.start() + + signal.signal(signal.SIGUSR1, debug_thread.handler) signal.signal(signal.SIGTERM, exit_handler) + loop = gobject.MainLoop() try: options = parse_options() diff --git a/mopidy/utils/process.py b/mopidy/utils/process.py index 80d850fe..fdeb8e8c 100644 --- a/mopidy/utils/process.py +++ b/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,9 @@ from mopidy import SettingsError 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...') thread.interrupt_main() @@ -17,8 +22,6 @@ 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]) exit_process() @@ -65,3 +68,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: + continue + + print "## Thread: %s (%s) ##" % (threads[ident], ident) + print ''.join(traceback.format_stack(frame)) + + self.event.clear() From 6bee352f477967b0b27591d796b75ab22352dba6 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Sun, 16 Sep 2012 16:24:36 +0200 Subject: [PATCH 2/5] Move trackback dumping to logger. --- mopidy/utils/process.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/mopidy/utils/process.py b/mopidy/utils/process.py index fdeb8e8c..909fe7c1 100644 --- a/mopidy/utils/process.py +++ b/mopidy/utils/process.py @@ -85,10 +85,10 @@ class DebugThread(threading.Thread): threads = dict((t.ident, t.name) for t in threading.enumerate()) for ident, frame in sys._current_frames().items(): - if self.ident == ident: - continue - - print "## Thread: %s (%s) ##" % (threads[ident], ident) - print ''.join(traceback.format_stack(frame)) + 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() From 81a3b41bc40494063c52d5447e184ebef5020241 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Thu, 8 Nov 2012 22:54:35 +0100 Subject: [PATCH 3/5] Add flag and setting for thread deadlock debug tool. --- mopidy/__main__.py | 14 ++++++++++---- mopidy/settings.py | 8 ++++++++ 2 files changed, 18 insertions(+), 4 deletions(-) diff --git a/mopidy/__main__.py b/mopidy/__main__.py index b312840e..de905d15 100644 --- a/mopidy/__main__.py +++ b/mopidy/__main__.py @@ -40,14 +40,16 @@ logger = logging.getLogger('mopidy.main') def main(): - debug_thread = process.DebugThread() - debug_thread.start() - - signal.signal(signal.SIGUSR1, debug_thread.handler) 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() @@ -104,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] diff --git a/mopidy/settings.py b/mopidy/settings.py index fbc71f0e..12acd281 100644 --- a/mopidy/settings.py +++ b/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`. From a4caf998bdf87c59fa1e2c0a8453e19f42c4d2b6 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Thu, 8 Nov 2012 22:57:11 +0100 Subject: [PATCH 4/5] Add debug thread feature to changelog. --- docs/changes.rst | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/docs/changes.rst b/docs/changes.rst index a01eb1c7..594b5496 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -88,6 +88,10 @@ backends: - Added support for search by filename to local backend. +- Added optional background thread for debuging 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 From 812733205fa6c62c6ea6ec1d4229c9d6abd60131 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Thu, 8 Nov 2012 23:06:38 +0100 Subject: [PATCH 5/5] Add notes about debug thread to development docs. --- docs/changes.rst | 2 +- docs/development.rst | 11 +++++++++++ 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/docs/changes.rst b/docs/changes.rst index 594b5496..a36ee180 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -88,7 +88,7 @@ backends: - Added support for search by filename to local backend. -- Added optional background thread for debuging deadlocks. When the feature is +- 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. diff --git a/docs/development.rst b/docs/development.rst index 6cab7bf1..00a1d46a 100644 --- a/docs/development.rst +++ b/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 =====================