diff --git a/README.rst b/README.rst index 2dbe128c..a4716738 100644 --- a/README.rst +++ b/README.rst @@ -148,6 +148,28 @@ Install `VSCode `_ Then to debug, click View -> Output and in the dropdown will be pyls. To refresh VSCode, press `Cmd + r` +Diagnosing slow requests +------------------------ + +Requests are handled one at a time, so a single slow plugin delays everything queued +behind it and the editor can appear to hang. When a hook takes longer than a second the +server logs a warning naming the hook, the document and the plugins registered for that +hook, for example:: + + Hook pyls_lint took 118.62s for file:///home/me/project/big.py. Plugins registered + for this hook: mccabe, pycodestyle, pyflakes. Requests are handled one at a time, so + a slow plugin delays everything behind it. + +That narrows a hang to one hook and a small set of plugins. To confirm which plugin is +responsible, disable them one at a time with the ``pyls.plugins..enabled`` setting. + +Every hook call is also timed at debug level, so running the server with ``-v`` shows +timings for requests that completed normally. + +When reporting a slow request, please include these lines along with the output of +``pip list``: how long a request takes depends heavily on the size of the environment +Jedi has to search. + License ------- diff --git a/pyls/python_ls.py b/pyls/python_ls.py index 0a11aa9b..da848a4b 100644 --- a/pyls/python_ls.py +++ b/pyls/python_ls.py @@ -4,6 +4,7 @@ import os import socketserver import threading +from timeit import default_timer from pyls_jsonrpc.dispatchers import MethodDispatcher from pyls_jsonrpc.endpoint import Endpoint @@ -17,12 +18,46 @@ LINT_DEBOUNCE_S = 0.5 # 500 ms +# A hook taking longer than this is reported at WARNING so a slow request shows up in a +# user's log without them having to enable debug logging first. Requests are expected to +# complete in milliseconds, so anything at this scale is already user-visible. +SLOW_HOOK_S = 1.0 PARENT_PROCESS_WATCH_INTERVAL = 10 # 10 s MAX_WORKERS = 64 PYTHON_FILE_EXTENSIONS = ('.py', '.pyi') CONFIG_FILEs = ('pycodestyle.cfg', 'setup.cfg', 'tox.ini', '.flake8') +def _hook_plugin_names(hook_handlers): + """Return the plugins registered for a hook, for attributing a slow call. + + Only called when a hook was slow, so the cost does not land on every request. + """ + try: + return sorted(impl.plugin_name for impl in hook_handlers.get_hookimpls()) + except Exception: # pylint: disable=broad-except + # Attribution is a nicety. Never let it turn a slow request into a failed one. + return [] + + +def _log_hook_duration(hook_name, doc_uri, hook_handlers, duration): + """Record how long a hook took, loudly if it was slow. + + Requests are dispatched to every plugin registered for a hook, so a single slow + plugin stalls the whole request. Without this there is no way for a user reporting + a hang to say which hook or plugin was responsible. + """ + if duration < SLOW_HOOK_S: + log.debug("Hook %s took %.3fs (%s)", hook_name, duration, doc_uri) + return + + log.warning( + "Hook %s took %.2fs for %s. Plugins registered for this hook: %s. " + "Requests are handled one at a time, so a slow plugin delays everything behind it.", + hook_name, duration, doc_uri, ', '.join(_hook_plugin_names(hook_handlers)) or 'unknown', + ) + + class _StreamHandlerWrapper(socketserver.StreamRequestHandler, object): """A wrapper class that is used to construct a custom handler class.""" @@ -153,7 +188,15 @@ def _hook(self, hook_name, doc_uri=None, **kwargs): workspace = self._match_uri_to_workspace(doc_uri) doc = workspace.get_document(doc_uri) if doc_uri else None hook_handlers = self.config.plugin_manager.subset_hook_caller(hook_name, self.config.disabled_plugins) - return hook_handlers(config=self.config, workspace=workspace, document=doc, **kwargs) + # default_timer is the best clock available on both Python 2 and 3; + # time.perf_counter does not exist on 2.7, which this package still supports. + start = default_timer() + try: + return hook_handlers(config=self.config, workspace=workspace, document=doc, **kwargs) + finally: + # In a finally block so a hook that raises is still accounted for; an + # exception after a long wait is exactly the case worth seeing in a log. + _log_hook_duration(hook_name, doc_uri, hook_handlers, default_timer() - start) def capabilities(self): server_capabilities = { diff --git a/test/test_hook_timing.py b/test/test_hook_timing.py new file mode 100644 index 00000000..ef7ae9b2 --- /dev/null +++ b/test/test_hook_timing.py @@ -0,0 +1,102 @@ +# Copyright 2017 Palantir Technologies, Inc. +import logging +import time + +try: + from unittest import mock +except ImportError: + import mock + +from pyls import python_ls +from pyls.python_ls import PythonLanguageServer + + +class FakeHookCaller(object): + """Stands in for a pluggy hook caller so a hook can be made slow on demand.""" + + def __init__(self, delay=0.0, plugin_names=(), exception=None): + self.delay = delay + self.plugin_names = list(plugin_names) + self.exception = exception + + def __call__(self, **_kwargs): + if self.delay: + time.sleep(self.delay) + if self.exception: + raise self.exception + return ['result'] + + def get_hookimpls(self): + return [mock.Mock(plugin_name=name) for name in self.plugin_names] + + +def _server(hook_caller): + server = PythonLanguageServer(mock.Mock(), mock.Mock()) + server.config = mock.Mock() + server.config.disabled_plugins = [] + server.config.plugin_manager.subset_hook_caller.return_value = hook_caller + workspace = mock.Mock() + workspace.get_document.return_value = None + server._match_uri_to_workspace = lambda _uri: workspace # pylint: disable=protected-access + return server + + +def test_fast_hook_is_not_warned_about(caplog): + server = _server(FakeHookCaller(plugin_names=['jedi_hover'])) + with caplog.at_level(logging.DEBUG, logger=python_ls.__name__): + result = server._hook('pyls_hover', 'file:///tmp/a.py') # pylint: disable=protected-access + + assert result == ['result'] + assert not [r for r in caplog.records if r.levelno >= logging.WARNING] + assert any('pyls_hover' in r.getMessage() for r in caplog.records) + + +def test_slow_hook_is_reported_with_the_plugins_that_ran(caplog, monkeypatch): + # Lowered so the test does not have to actually be slow. + monkeypatch.setattr(python_ls, 'SLOW_HOOK_S', 0.01) + server = _server(FakeHookCaller(delay=0.02, plugin_names=['pyflakes', 'pycodestyle'])) + + with caplog.at_level(logging.DEBUG, logger=python_ls.__name__): + server._hook('pyls_lint', 'file:///tmp/a.py') # pylint: disable=protected-access + + warnings = [r.getMessage() for r in caplog.records if r.levelno >= logging.WARNING] + assert len(warnings) == 1 + assert 'pyls_lint' in warnings[0] + assert 'file:///tmp/a.py' in warnings[0] + # The point of the message: which plugins could be responsible. + assert 'pycodestyle' in warnings[0] + assert 'pyflakes' in warnings[0] + + +def test_slow_hook_is_reported_even_when_it_raises(caplog, monkeypatch): + """An exception after a long wait is exactly the case worth seeing in a log.""" + monkeypatch.setattr(python_ls, 'SLOW_HOOK_S', 0.01) + server = _server(FakeHookCaller(delay=0.02, plugin_names=['pylint'], + exception=ValueError('plugin failed'))) + + with caplog.at_level(logging.DEBUG, logger=python_ls.__name__): + try: + server._hook('pyls_lint', 'file:///tmp/a.py') # pylint: disable=protected-access + raise AssertionError('expected the hook exception to propagate') + except ValueError: + pass + + warnings = [r.getMessage() for r in caplog.records if r.levelno >= logging.WARNING] + assert len(warnings) == 1 + assert 'pyls_lint' in warnings[0] + + +def test_attribution_failure_does_not_break_the_request(caplog, monkeypatch): + """Naming the plugins is a nicety and must never fail the request.""" + monkeypatch.setattr(python_ls, 'SLOW_HOOK_S', 0.01) + hook_caller = FakeHookCaller(delay=0.02, plugin_names=['pyflakes']) + hook_caller.get_hookimpls = mock.Mock(side_effect=RuntimeError('pluggy changed')) + server = _server(hook_caller) + + with caplog.at_level(logging.DEBUG, logger=python_ls.__name__): + result = server._hook('pyls_lint', 'file:///tmp/a.py') # pylint: disable=protected-access + + assert result == ['result'] + warnings = [r.getMessage() for r in caplog.records if r.levelno >= logging.WARNING] + assert len(warnings) == 1 + assert 'unknown' in warnings[0]