Perf CRITICAL: F12 (onDefinition) took 54s with a 38s synchronous event-loop freeze on the real solution

[msarson]

Symptom ([358 BUILD] retest, 2026-07-14 — F12 on IBSCommon.clw, ~1 min after startup settled)

[11:38:54.524] LSP slow handler | kind=request, method=onDefinition, ms=53899
[11:38:54.524] EventLoop lag | max_blocked_ms=38388, since_module_load_ms=90318

A single Go To Definition took 53.9 seconds, of which 38.4 seconds was one contiguous synchronous event-loop block — the editor was frozen solid for 38s. The F12 resolved to SelectJobNumber_IBSCommon.clw (opened immediately after), so it was a real navigation, but the cost is catastrophic and it is the single worst interactive stall observed in any retest (prior banked note had F12 at 14.9s QUEUED; this is far worse and largely SYNCHRONOUS, not just queued).

What is known

• connection.onDefinition (server.ts:2830) is a thin wrapper over definitionProvider.provideDefinition(document, position). The 38s synchronous block is inside that call (or something it invokes) — no yield points, so the whole editor froze.
• Concrete gap: onDefinition does NOT pass a cancellation token to provideDefinition, whereas onImplementation DOES pass one to provideImplementation (server.ts:2858-2873). So a slow F12 cannot be cancelled even if the user gives up. (Cancellation only helps if the provider has await/yield points — see below.)
• The definition provider has many resolution tiers (local → MEMBER parent → include chain → SDI → cross-file). One of them did ~38s of unyielded synchronous work on this symbol. Likely suspects given prior findings: repeated synchronous tokenization of the 873KB IBSCommon parent, an unbounded include-chain / candidate walk, or a FAR-style whole-solution scan on a procedure name.

Fix direction (investigate-first — do NOT guess the tier)

1. Instrument provideDefinition with a per-tier perf breakdown (mirror the undeclaredVar augment detail line: which tier, which symbol, ms each). Ship the instrumentation, get one more F12 log — that names the 38s culprit precisely.
2. Pass a cancellation token to provideDefinition (parity with onImplementation) so a giving-up user aborts it.
3. Once the culprit tier is known: add yield points / a bound / a cache so it can never block the loop for tens of seconds (the interactive-request-priority principle — F12/hover must never freeze the editor).

Priority

This is now the top user-facing pathology — a 38s frozen editor on a routine F12 is worse than any startup cost. Surfaced by the #358 retest (which fixed the undeclaredVar cost that previously dominated). Related: banked "interactive-request priority" item; #295 (off-thread); #359 (doc concurrency).

[msarson]

Instrumentation shipped — 06bf1b8 ([360-INSTR BUILD])

Built exactly the measurement Mark specified. DefinitionTrace threads through provideDefinition and emits one Definition trace perf line per slow/cancelled F12 with:

symbol, route, elapsed_ms, max_sync_slice_ms, attributed_ms, unattributed_ms, candidate_count, files_examined, cache_hits, cache_misses, fallback_entered, cancelled, phases

The load-bearing field is max_sync_slice_ms — the longest stretch the loop went without a tick, measured by a self-rescheduling setImmediate heartbeat (starved during a synchronous block, so the gap == block duration). This is the await-latency-vs-continuous-block discriminator: a phase awaiting queued work keeps the heartbeat ticking (small slice); a phase blocking continuously starves it (slice ≈ phase ms). Pinned by tests (150ms block → slice ≥100ms; same wall-clock awaited → <80ms).

Heavy tail routes timed explicitly: symbolDefinition (the "runs for minutes" prime suspect), structureDefinition, classTypeDefinition, typeInIncludes, fileReference. The unattributed_ms bucket catches a culprit outside those. onDefinition now threads the LSP cancel token (parity with onImplementation); a between-phase checkpoint early-outs, and the trace records cancelled — deep in-resolver cancellation is the phase-2 fix.

Next: one more F12 on the same symbol/shape as the 54s freeze. The Definition trace line will read out route=X, phases=X=38000, max_sync_slice_ms=38000 (or a large unattributed_ms) — that names the culprit tier precisely, and phase 2 fixes it (yields / bound / cache + real cancellation).

[msarson]

Verified fixed — closing on the freeze scope

Re-measured 2026-07-18 with a cold headless run on the real solution (ap1.sln, all caches wiped, IBSCommon.clw — the original repro file):

F12 NetDebugTrace  cold  2,293ms  locations=1   (was ~54s wall)
F12 NetDebugTrace  warm    262ms  locations=1
worst max_blocked_ms anywhere in the run: 3,531  (was 38,416 — and today's blocks are the
prewarm lane's atomic big-file tokenizes, not the definition walk)

The 38s synchronous onDefinition freeze this issue instrumented is gone — killed by the #361 pair (SDI gate on the type walk 26b508a6, yielding+memoized procedure walk b0d0e848) plus the findSymbolDefinition result cache (1b1b5f2a) and the #362 proc-index fast path.

One leftover found during this verification and split out as #374: F12 on a word that can never resolve (measured on the built-in LONGPATH) still runs a ~24s yielding cold walk through the startup window before returning nothing (36ms warm). Different pathology (miss-path wall time, not a freeze) — tracked there with the full log.