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

[ZayanKhan-12]

Description

Refs #257.

This is instrumentation, not a fix for any particular slow plugin, and I would not close #257 on it. It is the step the thread converged on: @ferozco proposed making hover async, @gatesn pushed back that this would "very quickly just end up starving the executor pool" and said "let's try and find the root cause" and "would be happy to add some log lines into the hover provider to help with timings", and @evandrocoan's first question was "why pyls would take so long to respond to a request?".

That work was never done. grep -rniE "time\.time|perf_counter|elapsed|duration" pyls/ returns nothing today, so a user whose editor freezes for two minutes has no way to say which hook or plugin was responsible, and nobody can act on the report.

Every request goes through _hook, which dispatches to all plugins registered for that hook, and requests are handled one at a time — so one slow plugin stalls everything queued behind it. Hook calls are now timed:

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 turns "pyls hangs" into one hook and a short list of candidates, which the user can then narrow with pyls.plugins.<name>.enabled. Calls under a second are logged at debug, so -v gives timings for healthy requests too.

Three details worth calling out:

• The timing is in a finally, so a hook that raises after a long wait is still reported. An exception arriving after 30 seconds is exactly the case worth seeing.
• Plugin attribution is best effort and wrapped: it only runs when the call was already slow, so it costs nothing on the hot path, and a pluggy API change cannot turn a slow request into a failed one.
• timeit.default_timer, not time.perf_counter, because this package still supports Python 2.7 and perf_counter does not exist there.

What I found while investigating

I profiled a hover to check whether there was a fixable hotspot in pyls itself before reaching for instrumentation. Warm hover on stdlib imports is about 1 ms, so the reported two minutes is Jedi inference over the reporter's environment — he mentioned roughly 200 Sublime packages on the path — which matches @gatesn's suspicion about large modules. There is no single pyls-side hotspot I could demonstrate, which is precisely why attribution is the thing that is missing.

One genuine inefficiency did turn up, and I deliberately left it out of this PR rather than bundling an unrelated change into a diagnostics one. Document.lines re-splits the whole source on every access, and several callers touch it twice per diagnostic, e.g. pylint_lint.py:121:

'character': len(document.lines[line]) if document.lines else 0,

Measured cost of that pattern:

file size	per .lines access	200 diagnostics × 2 accesses
1,000 lines	0.030 ms	12 ms
5,000 lines	0.151 ms	60 ms
20,000 lines	0.635 ms	254 ms

Real, but a quarter of a second in a pathological case — nowhere near the reported two minutes, so it is not the cause here. Caching it needs invalidation wherever _source is reassigned, which is a change I would rather make on its own with its own tests. Happy to open that separately if you want it.

Tests

Four tests in test/test_hook_timing.py: a fast hook produces no warning, a slow hook produces exactly one warning naming the hook, document and plugins, a slow hook that raises is still reported and the exception still propagates, and a failure inside attribution does not break the request.

I checked they hold the line by re-breaking the code three ways: removing the instrumentation fails all 4, moving the log out of the finally fails the raising case, and dropping the attribution guard fails the last one.

Verification

Python 3.8 with jedi 0.17.2, matching the CI matrix. A clean checkout of develop does not produce a clean run, so I recorded a baseline and compared:

	baseline	with this change
pytest test/	12 failed, 99 passed, 8 skipped	12 failed, 103 passed, 8 skipped
failing test names	—	identical set
pycodestyle pyls test	clean	clean
pyflakes pyls test	1 pre-existing (_utils.py)	unchanged
pylint pyls test	84 messages	no new message types

The 12 failures are pre-existing and track linter versions that moved on since 2020.

The README gains a short "Diagnosing slow requests" section, since the warning is only useful if people know it exists and know to include pip list when reporting. README.rst is used as long_description in setup.py, so I checked it still parses with docutils; the only warning is a pre-existing one at line 74 from markdown-style fences.

Note on scope

The threshold is a module constant (SLOW_HOOK_S). I kept it out of the config schema to avoid adding a setting for something most users never touch, but it is a one-line change to make configurable if you would prefer that.

CLAUDE.md lives in my other open PR (#982) and is deliberately not duplicated here so the branches do not conflict.

[palantirtech]

Thanks for your interest in palantir/python-language-server, @ZayanKhan-12! Before we can accept your pull request, you need to sign our contributor license agreement - just visit https://cla.palantir.com/ and follow the instructions. Once you sign, I'll automatically update this pull request.