perf(httpapi): measure workspace search per phase, inside the handler - #264
Merged
Conversation
Stage 1 of the three-stage search-perf plan. It builds nothing faster; it exists so stages 2 and 3 are not guesses. The previous round of work budgeted a 10.5 s workspace query by measuring the dense scan, the BM25 query and the fan-out's parallel speedup separately and multiplying. The budget closed, which is not the same as being right, and two optimisations were about to be built on it. One of the two multiplicands turned out to be off by 18x. What lands: - searchtimings.go: a searchPhases accumulator. Serial phases (embed, stale-FTS probe, fan-out wall, fuse) are plain durations; the two per-project phases keep a SUM and a MAX behind atomics, because the sum is the work the query did and the max is what the user waited for, and under sublinear parallelism those are different questions. Reporting either one alone hides which. - The fan-out records dense and BM25 per project (workspacesearch.go). - projects_scanned / projects_returned, because their ratio is the premise of stage 3: the fan-out does full work on every project and then thresholds the answer down. Always collected, conditionally reported. The measurement costs a handful of time.Now() calls and two atomics against a query that reads gigabytes, so there is no reason to gate the collection. Where it goes is gated twice, and the two gates answer different questions: - the LOG line fires only above slowWorkspaceQuery (2 s). The server already writes one http_request line per request carrying the wall time, so a second line on every workspace query would be noise added to catch the rare slow one. A threshold keeps the property a ?debug flag cannot have: nobody needs to have switched anything on before the slow query happened. Two seconds is not "wrong" for a fan-out over every project in a workspace — it is the point past which the breakdown is worth storing, and low enough that a regression on a small workspace still trips it. - the RESPONSE object is attached only for ?timings=true, documented as WorkspaceSearchTimings in doc/openapi.yaml. In a response this is a debugging aid, not API surface: every existing caller (CLI, MCP tools, dashboard) gets byte-identical responses to before. One deliberate omission versus the spec in the plan: no hydrate_ms. Chunk payloads are hydrated inside VectorStore.Search and chunksfts.SearchProject, so hydration is not separable from out here; it is inside dense_sum_ms/bm25_sum_ms and addDense says so. Everything after fuse is in-memory slicing. Measured on the fixture, wall minus the four serial phases is ~19 ms of 9,911 ms, so nothing material is unaccounted for. What it measured, on the 45-repo fixture (1.9M chunks, voyage-code-3 @2048, 14-core Mac, int8 scan on), 10 queries against the 43-project workspace, via loadtests/bench/phases.py — medians: wall 9,911 ms | fan-out 9,663 | BM25 sum 93,345 (max 3,210) dense sum 26,476 (max 2,428) | embed 218 | stale-FTS 11 | fuse 0 Dense is a constant; BM25 is the variable and wall tracks it — 78% of the fan-out's work at the median, ranging 15,026-183,177 ms with the number and length of query terms rather than with repo size, because MATCH is evaluated over the whole server's chunks_fts and filtered by project afterwards, once per repo. Two estimates it disproved: - a repo's BM25 measures 326-542 ms standalone (loadtests/bench/ftstest, through the server's own driver) but up to 5,767 ms inside the fan-out. 43 concurrent FTS queries against one index degrade each other by roughly an order of magnitude. Stage 2 removes 42/43 of that work AND the contention, so it is worth more than it looked, not less. - the stale-FTS probe costs 11 ms through the server, not the 0.2 ms a Python-side measurement suggested. Tests assert shape and gating, never wall-clock values. Every field present when asked for; no timings block at all when not asked for, or on a response that ran no search (zeroes would read as "instant"); the counters matching the fan-out actually performed; max <= sum per phase, which is what catches a sum and a max wired to the wrong accumulator; and both sides of the log threshold, from one captured logger, because a test that only proves silence would still pass if the line were deleted. slowWorkspaceQuery is a var rather than a const purely so that test can cross the threshold without sleeping; nothing at runtime writes it. Each gate was mutation-checked: removing the opt-in, removing the threshold, and deleting the log line each fail the suite. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…early returns, F3 wall coverage F1 (the one that mattered): projects_returned reported the count the caller was SHOWN, not the count that survived the relevance threshold. It was taken from projectPayloads, which is already truncated to top_projects (default 10, clamped 1..50). So on the 43-project fixture the scanned:returned ratio read 43:10 whether ten repos were relevant or forty, and it moved when a client passed a different top_projects — a request parameter, not a measurement of discarded work. That ratio is the stated premise of stage 3, so the metric two optimisations were going to rest on was measuring a UI cap. Now returned is len(surviving), and the panel count keeps its own field, projects_in_panel, because "what did the caller get" is a real but different question. F2: both early returns (no visible members, no indexed projects) passed a literal nil and never entered the reporter, so the log threshold and the response opt-in — documented as independent gates — were both off together on those paths. The query embedding has already been paid for by then (218 ms median on the fixture), and a hung embedding provider is exactly what the slow-query line is for. They now report with requested=false: no timings in the response, because nothing was searched, but a slow one still writes its line. F3: wall_ms was documented as "the whole handler" but started after requireWorkspaceVisible and the parameter clamps, and the unnamed remainder silently absorbed the membership SQL and access.AccessibleProjectHostPaths — the one pre-fan-out step that grows with how many projects the caller can see rather than with the workspace, and the one the fixture cannot exercise because an admin (and AuthDisabled) skips the ACL branch entirely. started now sits on the handler's first line, and the resolve phase gets its own resolve_ms. The spec now also states what the remainder is rather than implying there is none. Also from the review, documentation-only: - dense_sum_ms/bm25_sum_ms include projects whose query failed. Keeping them is correct — the time was spent, and excluding it would put the sums permanently below the wall time they exist to explain — but a slow failure can own the max, so both the spec and addDense now say so. - the comment on slowWorkspaceQuery now names the condition its test-only mutability depends on: nothing in this package calls t.Parallel(), and whoever adds the first parallel test here has to move the threshold onto Deps first or hit a data race under -race with a non-obvious cause. Two new tests, both mutation-checked against the bugs they describe: restoring the panel-capped counter fails the F1 test (reports 10, wants 14), and restoring the nil early return fails the F2 test. Not covered: an unrecorded resolve_ms still passes, because a shape test cannot tell an unset duration from a fast one. go test ./... green (46 packages), go test -race on the httpapi package green, make openapi-check in sync, go vet and gofmt clean. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Follow-up nit from the PR #264 review. reportSearchTimings takes the three project counters as consecutive ints — scanned, returned, panel — which is the signature where a transposition compiles, produces plausible numbers, and stays invisible until someone reasons from the scanned:returned ratio. That ratio is stage 3's premise, and getting it silently wrong is the exact failure F1 already was once. The chained inequality is the only relationship that holds unconditionally: the panel is a cap on what survived, and what survived is a subset of what was searched. Asserted from both tests that read timings, via a shared helper, so it applies to any future one too. Mutation-checked: swapping returned and panel at the call site trips both the F1 test and the new invariant. Co-Authored-By: Claude Opus 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
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.
Stage 1 of the three-stage search-perf plan that follows #263. It makes nothing
faster. It exists so stages 2 and 3 are not guesses.
Why a diagnostic gets its own PR
The last round budgeted the 10.5 s workspace query by measuring the dense scan,
the BM25 query and the fan-out's parallel speedup separately and multiplying
them together. The budget closed — which is not the same as being right. Two
optimisations were about to be built on it, and one of the multiplicands was off
by 18x.
What lands
internal/httpapi/searchtimings.go— asearchPhasesaccumulator. The serialphases (embed, stale-FTS probe, fan-out wall, fuse) are plain durations; the
two per-project phases keep a sum and a max behind atomics. The sum is the
work the query did, the max is what the user waited for, and under sublinear
parallelism those are different questions — eight concurrent project searches
measured 3.4x faster than the same eight in sequence, so the wall time sits
between the two numbers and reporting one alone hides which.
INFOline per workspace query, plus atimingsobject on the response,documented as
WorkspaceSearchTimingsindoc/openapi.yaml.projects_scanned/projects_returned, because their ratio is the premiseof stage 3: the fan-out does full work on every project and then thresholds
the answer down.
Always measured, conditionally reported
Collection is unconditional — it costs a handful of
time.Now()calls and twoatomics against a query that reads gigabytes. Where the numbers go is gated
twice, and the gates answer different questions:
http_requestline per request carrying the wall time, so a second line onevery workspace query would be noise added in order to catch the rare slow
one. A threshold keeps the one property a
?debugflag cannot have: nobodyneeds to have switched anything on before the slow query happened. Two
seconds is not "wrong" for a fan-out over every project in a workspace — it is
the point past which the breakdown is worth storing, and low enough that a
regression on a small workspace still trips it.
?timings=true. In a response this is adebugging aid, not API surface. Every existing caller — CLI, MCP tools,
dashboard — gets byte-identical responses to before.
One omission versus the plan's spec
No
hydrate_ms. Chunk payloads are hydrated insideVectorStore.Searchandchunksfts.SearchProject, so hydration is not separable from the handler; it isinside
dense_sum_ms/bm25_sum_msandaddDensesays so. Everything afterfuse is in-memory slicing. On the fixture, wall minus the four serial phases is
~19 ms of 9,911 ms, so nothing material is unaccounted for.
What it measured
45-repo fixture (1.9M chunks, voyage-code-3 @2048), 14-core Mac, int8 scan on,
10 queries against the 43-project workspace, via
loadtests/bench/phases.py.Dense is a constant; BM25 is the variable and wall tracks it — 78% of the
fan-out's work at the median. Its cost follows the number and length of query
terms rather than repo size, because
MATCHis evaluated over the wholeserver's
chunks_ftsand filtered by project afterwards, once per repo.Two estimates it disproved:
loadtests/bench/ftstest,through the server's own driver) but up to 5,767 ms inside the fan-out.
43 concurrent FTS queries against one index degrade each other by roughly an
order of magnitude. Stage 2 (one workspace-wide FTS query) removes 42/43 of
that work and the contention — worth more than it looked, not less.
Python-side measurement suggested.
Tests
Shape and gating, never wall-clock values — a bound on
dense_sum_mswould failon a loaded runner and teach everyone to ignore the test. Asserted: every field
present when asked for; no
timingsblock when not asked for, or on aresponse that ran no search (zeroes would read as "instant"); the counters
matching the fan-out actually performed;
max <= sumper phase, which catches asum and a max wired to the wrong accumulator; and both sides of the log
threshold from one captured logger, because a test that only proves silence
would still pass if the line were deleted outright.
slowWorkspaceQueryis avarrather than aconstpurely so that test can cross the threshold withoutsleeping; nothing at runtime writes it.
Each gate was mutation-checked — removing the opt-in, removing the threshold,
and deleting the log line each fail the suite.
Verification
go test ./...green (46 packages),make openapi-checkreportsopenapi.gen.goin sync,go vetclean,gofmtclean on the touched files.Rebased onto
develop@ a82ef2d.🤖 Generated with Claude Code
Review round (commit
d511513)F1 —
projects_returnedmeasured the panel cap, not the threshold. It camefrom
projectPayloads, already truncated totop_projects(default 10), so thescanned:returned ratio read 43:10 on the fixture whether ten repos were relevant
or forty — and moved when a client passed a different
top_projects. Since thatratio is the stated premise of stage 3, the metric two optimisations were going
to rest on was measuring a request parameter. Now
len(surviving); the panelcount keeps its own field,
projects_in_panel.F2 — early returns reported nothing at all. Both no-queryable-project paths
passed a literal
niland never entered the reporter, so the two gatesdocumented as independent were off together there.
embed_msis already paid bythat point, and a hung embedding provider is precisely what the slow-query line
is for. They now report with
requested=false: nothing in the response, but aslow one still writes its line.
F3 —
wall_msdid not cover the whole handler, and the unnamed remainderabsorbed
access.AccessibleProjectHostPaths— the one pre-fan-out step thatgrows with the caller's project count rather than the workspace, and the one the
fixture cannot exercise, since admin and
AuthDisabledskip the ACL branch.startedmoved to the handler's first line and the resolution step gotresolve_ms. The spec now states what the remainder is instead of implyingthere is none.
Documentation-only, from the same review:
dense_sum_ms/bm25_sum_msinclude projects whose query failed — keeping them is correct, since the time
was spent and excluding it would put the sums permanently below the wall time
they explain, but a slow failure can own the max, so the spec says so; and the
comment on
slowWorkspaceQuerynow names the condition its test-only mutabilitydepends on (nothing here calls
t.Parallel(); the first parallel test in thispackage has to move the threshold onto
Depsfirst).Both new tests were mutation-checked against the bugs they describe. Restoring
the panel-capped counter fails the F1 test; restoring the
nilearly returnfails the F2 test. Honestly not covered: an unrecorded
resolve_msstillpasses, because a shape test cannot tell an unset duration from a fast one.
What the corrected counter says (measured after
d511513)F1 was worth fixing for a concrete reason, now that the fixed counter has been
run against the fixture (branch build, two runs, counts identical in both since
they depend on scores rather than timing):
The plan's stated premise for stage 3 — "the fan-out does full work on all 45
repos and then thresholds down to 10, so three quarters of the work is thrown
away" — was reading the
top_projectscap. 77% of projects clear therelevance threshold, so the real over-scan is 1.3x, and the candidacy
distribution across a workspace is flat rather than peaked: the condition under
which bound-based pruning prunes nothing.
That does not change this PR, and it does not change stage 2 (which removes
42/43 of the BM25 work by asking once instead of 43 times, whatever the
threshold later decides). It does mean stage 3 has to be re-scoped or dropped
before anyone builds it — which is exactly the outcome a diagnostic is supposed
to produce, and the reason this PR is separate from the optimisations it is
meant to steer.