Add diagnostic instrumentation and regression-gate probes for issue #471 - #473
Merged
Merged
Conversation
Settles the "is request dispatch serial" question the issue leaves open: solo textDocument/foldingRange = 13.0ms; the same request fired concurrently with 20 textDocument/codeLens calls against the corpus's 1,350-step cache (BindingMatchService.FindUsages is an unindexed full-cache scan, called once per binding by StepCodeLensHandler) = 593.3ms. A cheap, unrelated request genuinely queues behind CodeLens/FindUsages work rather than running concurrently, confirming serial dispatch and corroborating FindUsages as the workload doing the blocking. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…gation Diagnostics-only change (item #2 of the investigation plan): once the concurrency probe confirmed serial dispatch and pointed at FindUsages as the blocking workload, the PERF log needed a way to correlate a climbing duration against what actually grew, from a live VS session, without re-deriving it from timestamps alone. - IOperationDurationRecorder.Measure/Record gain an optional `detail` string (source/binary-compatible trailing param); OperationDurationRecorder.Record now always logs the managed thread id too, so concurrent vs. serialized operations are directly visible in the log. - IBindingMatchService.GetCacheStats() reports (DocumentCount, TotalStepCount) cheaply (O(1) + O(cached docs)); StepCodeLensHandler tags its textDocument/codeLens PERF line with it, since FindUsages's cost is expected to track cached step count. - BindingRegistryChangedHandler's reconcile PERF line now carries the actual scanned/reparsed file counts, captured after the work runs (Measure's using-scope can't do this, so it moved to manual Stopwatch + try/finally, preserving record-on-exception behavior). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Two empirical duration-vs-size curves, without needing the full VS + Reqnroll.VeryLargeFeature manual repro: - Cache-size axis (bindings-in-file fixed at 64): 12.5ms at 2 features (~54 steps) to 44.3ms at 50 features (~1350 steps) - only ~3.5x for a 25x step-count increase; per-feature cost actually decreases. Sub-linear, not O(n^2), at this scale. - Bindings-in-file axis (cache fixed at 1350 steps): 64 bindings = 37.2ms, 1000 bindings (synthetic generated file) = 533.2ms - ratio tracks binding count almost exactly (15.6x bindings -> 14.3x latency, ~0.55ms/binding constant). Linear. Revises the working theory: FindUsages is linear in each axis individually, not O(n^2) in either alone, but cost is the product of both - and at the issue's real scale (~1,300-method file) that product alone reaches hundreds of ms per single CodeLens call, which combined with item #1's confirmed serial dispatch and VS's ~1/sec CodeLens polling is sufficient to explain the reported tens-of-seconds numbers. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Chris ran the F5/DEBUG experimental instance against Reqnroll.VeryLargeFeature and captured reqnroll-vs-server-debug-20260823-32140.log + reqnroll-vs-inspector-20260823-152122.log. Cross-referencing the two: - cacheDocs=1 cacheSteps=6238: a single .feature file is the "large .feature file" the issue described. - 10 consecutive textDocument/codeLens calls on the large step-definitions file, all at the same cache size, cost a stable ~1.22-1.29s each - confirms item #3's linear-in-the-product model with real data (~460 bindings implied). - internal/bindingRegistryReconcile (10050.2ms), textDocument/didOpen (10128.0ms), and the reqnroll/semanticTokens push (7470.8ms) all completed within ~2ms of each other on thread=20 - direct thread-sharing evidence. - reqnroll/resolveTestTargets fired 51 times in ~8 seconds for one open feature file - a previously unflagged contributor. - The clearest evidence yet for serial dispatch: VS acked the first workspace/inlayHint/refresh at 15:22:59.229, but the server's own SendRequest(...).ReturningVoid() didn't complete until 15:23:20.165 - ~21 seconds after VS's ack had already been sent. An already-received response frame sitting unprocessed because the server was busy with other queued work. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Two follow-up findings, posted to the issue and logged here: - Decompiled OmniSharp 0.19.9 to answer whether it supports concurrent dispatch: it does. Every handler this issue concerns is [Parallel] by the library's own interface attribute; textDocument/didOpen/didChange/didSave are hardwired [Serial], and the scheduler's batch design means a slow Serial item stalls the whole pipeline (including Parallel work queued behind it) until it drains. Revises "dispatch is effectively serial" to the more precise mechanism. - Audited range/resolve support per Chris's request: textDocument/codeLens has none at all (no resolveProvider, no resolve handler, no Data token on lenses) despite being the standard fix for exactly this eager-full-file cost shape; textDocument/semanticTokens/range and textDocument/inlayHint both accept a range but compute the whole document anyway before filtering/discarding down to it. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
ConcurrencyProbeTests and FindUsagesScalingProbeTests were diagnostic-only (log a finding, no assertion). Converts them to real pass/fail gates now that root cause is confirmed and findings are posted to issue #471: - ConcurrencyProbeTests: asserts the confirmed dispatch-stall symptom (>5x slowdown; real runs measured 40x-60x) still reproduces, plus a baseline sanity check. This documents known-bad behavior, not desired behavior -- flip or delete once the dispatch/CodeLens-resolve fix lands. - FindUsagesScalingProbeTests (both axes): asserts cost stays within a generous headroom (5x / 3x) of a naive linear-scaling prediction -- forward-compatible regression gates that catch a real O(n^2) regression without needing to change once FindUsages is eventually indexed. Also removes docs/Archive/Issue471-Investigation-TODO.md: scratch working notes for the investigation, per its own stated purpose now fulfilled -- all findings are posted to issue #471's comment thread instead. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Diagnostics-only infrastructure from the issue #471 investigation (LSP server scaling badly on large solutions) — no fix yet, that's tracked as follow-up work on a new branch once this merges. Full investigation writeup and findings are on the issue: #471.
IOperationDurationRecorder.Measure/Recordgain an optionaldetailstring tag (source/binary-compatible trailing param) and now always log the managed thread id, so PERF log lines can be correlated against the state that grew and against thread-sharing evidence directly from the log.IBindingMatchService.GetCacheStats()— cheap(DocumentCount, TotalStepCount)snapshot;StepCodeLensHandlertags its PERF line with it.BindingRegistryChangedHandler's reconcile PERF line now carries the actual scanned/reparsed file counts (captured after the work runs, via manualStopwatch+try/finallyinstead of theusing-scopeMeasureit replaced, preserving record-on-exception behavior).tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Performance/, both promoted from diagnostic probes to real regression gates:ConcurrencyProbeTests— asserts the confirmed dispatch-stall symptom (>5x slowdown on a cheap request under concurrent CodeLens load; real runs measured 40x-60x). Documents known-bad behavior — intentionally, per its own doc comment, to be flipped or removed once the dispatch/CodeLens-resolve fix lands.FindUsagesScalingProbeTests— two forward-compatible gates (headroom over a naive linear-scaling prediction on each axis) that catch a real O(n²) regression inFindUsages/CodeLens cost without needing changes once the underlying index work lands.BindingMatchService.GetCacheStats()and the recorder's newdetail/thread-id behavior.Test plan
dotnet build Reqnroll.IdeSupport.slnx— cleandotnet test tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests— 776/776 passingdotnet test tests/LSP/Reqnroll.IdeSupport.LSP.Core.Tests— 617/618 passing (1 pre-existing unrelated skip)🤖 Generated with Claude Code