Log how long each hook takes, loudly when it is slow

README.rst

@@ -148,6 +148,28 @@ Install `VSCode <https://code.visualstudio.com/download>`_
 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.<name>.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
 -------
 

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 = {

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]