code-index query costs ~10 minutes per invocation on Windows, and it has been silently consuming the CI budget #283

Closed
opened 2026-09-17 07:35:09 +02:00 by buildagent · 1 comment
Member

The measurement

From the Windows lane of run 824 (4e3106f), verbatim timestamps:

03:37:43  Running tests\query_cli.rs
03:38:43  test a_shell_caller_gets_the_disclosure_envelope_an_agent_gets has been running for over 60 seconds
03:38:43  test the_exit_code_separates_answered_refused_and_not_served    has been running for over 60 seconds
03:38:43  test the_list_names_the_tools_this_build_serves                 has been running for over 60 seconds
04:07:44  test the_list_names_the_tools_this_build_serves ... ok
04:07:49  test a_shell_caller_gets_the_disclosure_envelope_an_agent_gets ... ok
05:30:10  the runner cancelled the job because it exceeds the maximum run time

the_list_names_the_tools_this_build_serves makes one code-index query --list call. It took 30 minutes. the_exit_code_separates_answered_refused_and_not_served makes five calls and never finished inside the 3-hour job ceiling.

That puts one code-index query invocation at roughly ten minutes on Windows against a fresh project. On Linux the same call is 30–50 ms warm and about 2 s cold. That is a factor of ~300 against the cold Linux number.

Why it was invisible until now

The Windows lane was already running at 2h53m against a 3h ceiling when query_cli was introduced in #282 (run 816, beabeb8, green). It passed, so nothing reported a problem — the lane had seven minutes of headroom and no one was counting.

Adding one more integration test (blast_radius_hook, ~1 hour) pushed the total past the ceiling and the runner cancelled the job. The new test did not reveal a bug in itself; it spent a budget that was already gone.

A CI lane at 97% of its timeout is a failure that has not happened yet, and this one had no instrument pointed at it. cost-baseline.json prices SQLite work per pass; nothing prices wall-clock per lane.

Where the time is likely going

Not established — this is the part that needs measuring rather than guessing. The shape of the call is:

code-index query <tool> → spawns code-index-mcp
                        → which starts or attaches a daemon
                        → which reconciles the project
                        → initialize handshake, then one tools/call

--no-daemon is deliberately NOT passed (#282 requirement 2: a query must not become a second writer), so every invocation against a project with no running daemon pays a full cold daemon start. In CI that is every invocation, because each test uses a fresh temp project.

Ten minutes is far past what a cold start should cost even on slow storage, so something is probably retrying or waiting on a timeout rather than simply being slow. Candidates worth measuring first:

  1. daemon spawn/handshake retry on Windows — is there a poll loop with a long backoff?
  2. the lockfile / second-writer guard, if its Windows path waits where the Unix path does not;
  3. file watching setup over the temp directory;
  4. Server::spawn in crates/cli/src/query.rs — the reader thread and 60s RESPONSE_TIMEOUT bound one response, not the total, so repeated slow responses multiply.

What has been done meanwhile

blast_radius_hook's full-stack test is now #[cfg(unix)], with the measurement recorded at the test. That returns the lane to roughly its previous 2h53m — still marginal, and this issue is the reason it is marginal. The other three hook tests still run on Windows.

query_cli is untouched and still runs there, at ~30 minutes per test.

What would close this

A measured account of where a single code-index query spends ten minutes on Windows, and a fix that brings it to the same order as the Linux cold path. Failing that, a deliberate decision about what the Windows lane is for, since it currently cannot afford another integration test of any kind.

Related: #282 introduced the surface being measured here.

## The measurement From the Windows lane of run 824 (`4e3106f`), verbatim timestamps: ``` 03:37:43 Running tests\query_cli.rs 03:38:43 test a_shell_caller_gets_the_disclosure_envelope_an_agent_gets has been running for over 60 seconds 03:38:43 test the_exit_code_separates_answered_refused_and_not_served has been running for over 60 seconds 03:38:43 test the_list_names_the_tools_this_build_serves has been running for over 60 seconds 04:07:44 test the_list_names_the_tools_this_build_serves ... ok 04:07:49 test a_shell_caller_gets_the_disclosure_envelope_an_agent_gets ... ok 05:30:10 the runner cancelled the job because it exceeds the maximum run time ``` `the_list_names_the_tools_this_build_serves` makes **one** `code-index query --list` call. It took **30 minutes**. `the_exit_code_separates_answered_refused_and_not_served` makes five calls and never finished inside the 3-hour job ceiling. That puts one `code-index query` invocation at roughly **ten minutes** on Windows against a fresh project. On Linux the same call is **30–50 ms** warm and about **2 s** cold. That is a factor of ~300 against the cold Linux number. ## Why it was invisible until now The Windows lane was already running at **2h53m against a 3h ceiling** when `query_cli` was introduced in #282 (run 816, `beabeb8`, green). It passed, so nothing reported a problem — the lane had seven minutes of headroom and no one was counting. Adding one more integration test (`blast_radius_hook`, ~1 hour) pushed the total past the ceiling and the runner cancelled the job. The new test did not reveal a bug in itself; it spent a budget that was already gone. **A CI lane at 97% of its timeout is a failure that has not happened yet**, and this one had no instrument pointed at it. `cost-baseline.json` prices SQLite work per pass; nothing prices wall-clock per lane. ## Where the time is likely going Not established — this is the part that needs measuring rather than guessing. The shape of the call is: code-index query <tool> → spawns code-index-mcp → which starts or attaches a daemon → which reconciles the project → initialize handshake, then one tools/call `--no-daemon` is deliberately NOT passed (#282 requirement 2: a query must not become a second writer), so every invocation against a project with no running daemon pays a full cold daemon start. In CI that is every invocation, because each test uses a fresh temp project. Ten minutes is far past what a cold start should cost even on slow storage, so something is probably retrying or waiting on a timeout rather than simply being slow. Candidates worth measuring first: 1. daemon spawn/handshake retry on Windows — is there a poll loop with a long backoff? 2. the lockfile / second-writer guard, if its Windows path waits where the Unix path does not; 3. file watching setup over the temp directory; 4. `Server::spawn` in `crates/cli/src/query.rs` — the reader thread and 60s `RESPONSE_TIMEOUT` bound one *response*, not the total, so repeated slow responses multiply. ## What has been done meanwhile `blast_radius_hook`'s full-stack test is now `#[cfg(unix)]`, with the measurement recorded at the test. That returns the lane to roughly its previous 2h53m — **still marginal, and this issue is the reason it is marginal.** The other three hook tests still run on Windows. `query_cli` is untouched and still runs there, at ~30 minutes per test. ## What would close this A measured account of where a single `code-index query` spends ten minutes on Windows, and a fix that brings it to the same order as the Linux cold path. Failing that, a deliberate decision about what the Windows lane is for, since it currently cannot afford another integration test of any kind. Related: #282 introduced the surface being measured here.
Author
Member

Fixed by d4ea649. Windows lane green (run 829), and the measurement is the point of this issue, so here it is against the numbers filed above.

Same lane, same tests, with the fix

07:02:43.92  Running tests\query_cli.rs
07:02:45.08  the_list_names_the_tools_this_build_serves ... ok
07:02:45.17  a_one_shot_query_answers_without_starting_a_daemon ... ok
07:02:45.20  a_shell_caller_gets_the_disclosure_envelope_an_agent_gets ... ok
07:02:45.33  the_exit_code_separates_answered_refused_and_not_served ... ok
before after
one code-index query invocation ~10 min ~0.3 s
the_list_names_the_tools_this_build_serves (1 call) 30 min 1.16 s
the_exit_code_separates_… (5 calls) never finished in 3 h 0.13 s
query_cli whole binary >60 min, cancelled 1.4 s
the Windows lane 2h53m, then a 3 h timeout 56m8s

The lane now sits at ~31% of its ceiling instead of 97%.

The cause

attach_or_spawn_daemon waits DAEMON_READY_TIMEOUT (60s) for a daemon that says nothing, and up to DAEMON_STARTUP_CEILING — fifteen minutes — for one still reporting progress. Correct for a long-lived session, where one start serves everything after it. Wrong for a one-shot query, which pays the whole start, exits, and leaves behind a background process nobody asked for.

Guess (3) in the original triage — "file watching setup" — was wrong, and (1) was right in shape: not a retry loop but a deliberate readiness budget being charged to the wrong kind of caller.

The fix

code-index query ATTACHES when a daemon already serves the project, and otherwise answers in-process with --no-daemon. It never starts one.

The decision goes through lifecycle::live — the single probe guard_live_daemon refuses on and activation::owner withholds the writer lock on — rather than a second copy. Its three states matter: an unreadable probe takes the ATTACH path, because "I could not check" is not "nobody is there" and --no-daemon opens the index to write. Being slow is recoverable; two writers is not.

a_one_shot_query_answers_without_starting_a_daemon pins both halves — it still answers, and no daemon is registered afterwards. Either alone passes for the wrong reason, since a query that failed outright also leaves no daemon. MUTATION (RUN): drop the --no-daemon branch → RED on that test alone.

The part of this issue that was not about query

A CI lane at 97% of its timeout is a failure that has not happened yet, and this one had no instrument pointed at it.

That remains true and is not fixed here. cost-baseline.json prices SQLite work per pass; nothing prices wall-clock per lane, so the next slow thing to land will again be discovered by a cancellation rather than by a ratchet. Worth its own issue rather than being closed silently along with the cause that exposed it.

Follow-up being done now

blast_radius_hook's full-stack test was gated #[cfg(unix)] on the explicit grounds that it cost ~1 hour on Windows. That was true only because each of its four code-index query calls took ten minutes; at 0.3s they cost about a second in total. The gate's stated justification is now measurably false, so it is being removed rather than left as a stale cfg with an expired reason.

Fixed by `d4ea649`. Windows lane green (run 829), and the measurement is the point of this issue, so here it is against the numbers filed above. ## Same lane, same tests, with the fix ``` 07:02:43.92 Running tests\query_cli.rs 07:02:45.08 the_list_names_the_tools_this_build_serves ... ok 07:02:45.17 a_one_shot_query_answers_without_starting_a_daemon ... ok 07:02:45.20 a_shell_caller_gets_the_disclosure_envelope_an_agent_gets ... ok 07:02:45.33 the_exit_code_separates_answered_refused_and_not_served ... ok ``` | | before | after | |---|---|---| | one `code-index query` invocation | ~10 min | **~0.3 s** | | `the_list_names_the_tools_this_build_serves` (1 call) | 30 min | **1.16 s** | | `the_exit_code_separates_…` (5 calls) | never finished in 3 h | **0.13 s** | | `query_cli` whole binary | >60 min, cancelled | **1.4 s** | | the Windows lane | 2h53m, then a 3 h timeout | **56m8s** | The lane now sits at ~31% of its ceiling instead of 97%. ## The cause `attach_or_spawn_daemon` waits `DAEMON_READY_TIMEOUT` (60s) for a daemon that says nothing, and up to `DAEMON_STARTUP_CEILING` — **fifteen minutes** — for one still reporting progress. Correct for a long-lived session, where one start serves everything after it. Wrong for a one-shot query, which pays the whole start, exits, and leaves behind a background process nobody asked for. Guess (3) in the original triage — "file watching setup" — was wrong, and (1) was right in shape: not a retry loop but a deliberate readiness budget being charged to the wrong kind of caller. ## The fix `code-index query` ATTACHES when a daemon already serves the project, and otherwise answers in-process with `--no-daemon`. It never starts one. The decision goes through `lifecycle::live` — the single probe `guard_live_daemon` refuses on and `activation::owner` withholds the writer lock on — rather than a second copy. Its three states matter: an **unreadable** probe takes the ATTACH path, because "I could not check" is not "nobody is there" and `--no-daemon` opens the index to write. Being slow is recoverable; two writers is not. `a_one_shot_query_answers_without_starting_a_daemon` pins both halves — it still answers, and no daemon is registered afterwards. Either alone passes for the wrong reason, since a query that failed outright also leaves no daemon. MUTATION (RUN): drop the `--no-daemon` branch → RED on that test alone. ## The part of this issue that was not about `query` > A CI lane at 97% of its timeout is a failure that has not happened yet, and this one had no instrument pointed at it. That remains true and is not fixed here. `cost-baseline.json` prices SQLite work per pass; nothing prices wall-clock per lane, so the next slow thing to land will again be discovered by a cancellation rather than by a ratchet. Worth its own issue rather than being closed silently along with the cause that exposed it. ## Follow-up being done now `blast_radius_hook`'s full-stack test was gated `#[cfg(unix)]` on the explicit grounds that it cost ~1 hour on Windows. That was true only because each of its four `code-index query` calls took ten minutes; at 0.3s they cost about a second in total. The gate's stated justification is now measurably false, so it is being removed rather than left as a stale `cfg` with an expired reason.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
h-dv/code-index#283
No description provided.