Startup with language packages is about six times slower since v0.41.49; the v0.41.51 release run failed on it

buildagent commented

2026-11-12 22:02:47 +01:00

Member

What happened

The release run for the tag v0.41.51 (run 2591) failed in the job "Windows archive smoke (msvc)", so no release was created for that tag. In tests/release_language_smoke.ps1 the first code-index query search_symbols after a completed code-index index was refused:

search_symbols refused: index_incomplete
{"error":"index_incomplete", … "reconcile_pending":{"wait_budget_ms":10000,"converges_on_retry":true,"started_daemon":{"pid":29220,"started_by_this_call":true,"serving":true, …}}, "index_state":{"projects":{"primary":"warming_up"}},"retryable":true, …}

The script treats a non-zero exit as fatal. The daemon the call had started kept running, and the CI step did not end until the job's 30-minute timeout.

Cause: a regression that shipped in v0.41.49

The same step on earlier release runs (Windows runner, time from the languages list output to the script's last line):

release	`languages enable`	`index` + `languages list`	one-shot `query`
v0.41.48	14 s	5 s	3 s
v0.41.49	27 s	11 s	9.4 s
v0.41.50	27 s	11 s	9.8 s
v0.41.51	32 s	14 s	more than 10 s (refused)

The one-shot wait budget is 10 s, so v0.41.49 and v0.41.50 passed by a margin of 0.2–0.6 s.

Reproduced on Linux (12 cores, the released linux-x86_64 archives, the seven-language fixture tests/release-smoke/languages, all seven first-party packages enabled, fresh store, no daemon):

build	`languages enable`	`index`	one-shot `query`, first / second call
v0.41.48 (`81ff0158`)	13.6 s	3.5 s	1.4 s / 1.6 s
v0.41.49 (`a7ce9603`)	29.0 s	10.2 s	9.2 s / 9.7 s
v0.41.50 (`3d0a584c`)	25.5 s	9.5 s	8.5 s / 8.7 s
v0.41.51 tree, shipped shape (`5d31f4d9`)	25.5 s	9.3 s	8.5 s / 9.2 s

v0.41.51 did not make it slower; it ran on a slightly slower day.

The second query is as slow as the first: with no daemon running, every one-shot call on a project with seven enabled packages costs 8–9 s, although the index is complete and nothing is reparsed (parse_count: 0, stat_skipped: 7).

Debug timeline of one such call on v0.41.49 (CODE_INDEX_LOG=debug): "single-process startup: language enablement" 2.4 s, "bundled adoption" 1.4 s, "package host" 1.5 s, then 1.6 s, 0.9 s, 0.5 s, 0.35 s and 0.36 s between log lines that are adjacent on v0.41.48. v0.41.48 has one gap of 1.5 s (package discovery) and no other. The code is reconcile_local_snapshot in crates/mcp-server/src/main.rs, which since v0.41.49 calls packages::index_host twice and runs enablement, activation reconciliation, automatic enablement and bundled adoption around it. Which function costs what is not attributed yet.

Why no gate saw it

The workspace test build compiles every builtin parser in, and the same steps take 0.08 s there. Only the shipped shape (no builtin, seven packages) shows the cost.
The release smoke step asserts results and prints no timings.

Wanted

Attribution, then one mechanism: an expensive package step is paid once per process for an unchanged input, without weakening any verification.
A gate that counts that step in a single-process startup on a bench that loads real packages, so it cannot regress unnoticed. No wall-clock bound.
The release smoke script prints step timings, retries a refusal that is marked retryable for a bounded time and says so, and stops a daemon it started so the step can end.
Open question: why the Windows step did not end after the script had thrown (the daemon holding the caller's pipe, or the runner waiting for the process tree).

State of the v0.41.51 tag

The tag exists on 3c8742bf and has no release. The fixes it contains (#573, #575, #576, #578) are on master and ship with the next release.

## What happened The release run for the tag `v0.41.51` ([run 2591](https://git.h-dv.de/h-dv/code-index/actions/runs/2591)) failed in the job "Windows archive smoke (msvc)", so no release was created for that tag. In `tests/release_language_smoke.ps1` the first `code-index query search_symbols` after a completed `code-index index` was refused: ``` search_symbols refused: index_incomplete {"error":"index_incomplete", … "reconcile_pending":{"wait_budget_ms":10000,"converges_on_retry":true,"started_daemon":{"pid":29220,"started_by_this_call":true,"serving":true, …}}, "index_state":{"projects":{"primary":"warming_up"}},"retryable":true, …} ``` The script treats a non-zero exit as fatal. The daemon the call had started kept running, and the CI step did not end until the job's 30-minute timeout. ## Cause: a regression that shipped in v0.41.49 The same step on earlier release runs (Windows runner, time from the `languages list` output to the script's last line): | release | `languages enable` | `index` + `languages list` | one-shot `query` | |---|---|---|---| | v0.41.48 | 14 s | 5 s | 3 s | | v0.41.49 | 27 s | 11 s | 9.4 s | | v0.41.50 | 27 s | 11 s | 9.8 s | | v0.41.51 | 32 s | 14 s | more than 10 s (refused) | The one-shot wait budget is 10 s, so v0.41.49 and v0.41.50 passed by a margin of 0.2–0.6 s. Reproduced on Linux (12 cores, the released `linux-x86_64` archives, the seven-language fixture `tests/release-smoke/languages`, all seven first-party packages enabled, fresh store, no daemon): | build | `languages enable` | `index` | one-shot `query`, first / second call | |---|---|---|---| | v0.41.48 (81ff0158) | 13.6 s | 3.5 s | 1.4 s / 1.6 s | | v0.41.49 (a7ce9603) | 29.0 s | 10.2 s | 9.2 s / 9.7 s | | v0.41.50 (3d0a584c) | 25.5 s | 9.5 s | 8.5 s / 8.7 s | | v0.41.51 tree, shipped shape (5d31f4d9) | 25.5 s | 9.3 s | 8.5 s / 9.2 s | v0.41.51 did not make it slower; it ran on a slightly slower day. The second query is as slow as the first: with no daemon running, every one-shot call on a project with seven enabled packages costs 8–9 s, although the index is complete and nothing is reparsed (`parse_count: 0`, `stat_skipped: 7`). Debug timeline of one such call on v0.41.49 (`CODE_INDEX_LOG=debug`): "single-process startup: language enablement" 2.4 s, "bundled adoption" 1.4 s, "package host" 1.5 s, then 1.6 s, 0.9 s, 0.5 s, 0.35 s and 0.36 s between log lines that are adjacent on v0.41.48. v0.41.48 has one gap of 1.5 s (package discovery) and no other. The code is `reconcile_local_snapshot` in `crates/mcp-server/src/main.rs`, which since v0.41.49 calls `packages::index_host` twice and runs enablement, activation reconciliation, automatic enablement and bundled adoption around it. Which function costs what is not attributed yet. ## Why no gate saw it - The workspace test build compiles every builtin parser in, and the same steps take 0.08 s there. Only the shipped shape (no builtin, seven packages) shows the cost. - The release smoke step asserts results and prints no timings. ## Wanted 1. Attribution, then one mechanism: an expensive package step is paid once per process for an unchanged input, without weakening any verification. 2. A gate that counts that step in a single-process startup on a bench that loads real packages, so it cannot regress unnoticed. No wall-clock bound. 3. The release smoke script prints step timings, retries a refusal that is marked `retryable` for a bounded time and says so, and stops a daemon it started so the step can end. 4. Open question: why the Windows step did not end after the script had thrown (the daemon holding the caller's pipe, or the runner waiting for the process tree). ## State of the v0.41.51 tag The tag exists on `3c8742bf` and has no release. The fixes it contains (#573, #575, #576, #578) are on master and ship with the next release.

buildagent referenced this issue

2026-11-12 22:21:52 +01:00

The nightly runs have been red on 11 of 13 completed runs since 2026-11-06 and nothing reports it: overhead budgets, two intermittent startup failures, a step-guard cascade #582

buildagent referenced this issue

2026-11-12 22:23:11 +01:00

Retire crates/plugins: 24k lines of extractors no release contains are still maintained twice; default build differs from release #515

buildagent added the

labels

2026-11-12 22:23:30 +01:00

buildagent referenced this issue

2026-11-12 22:23:31 +01:00

The nightly runs have been red on 11 of 13 completed runs since 2026-11-06 and nothing reports it: overhead budgets, two intermittent startup failures, a step-guard cascade #582

buildagent commented

2026-11-12 23:53:19 +01:00

Author

Member

The cost grows with the package store (measured 2026-11-12)

The figures in the report were taken with only the seven first-party packages installed. With a store as a developer machine really has it (45 installed packages, 141 MiB, most of them not used by the project) the same steps cost:

step	v0.41.48	master `3c8742bf` (= v0.41.49 … v0.41.51 behaviour)	first fix candidate
`languages enable` (7 languages)	13.6 s	132.7 s	16.1 s
`index`	3.6 s	29.4 s	5.5 s
one-shot `query search_symbols`	1.4 s	17–19 s, the first call refused with `index_incomplete`	4.7–5.1 s

Same machine, shipped build shape, fresh project and no daemon; the store was seeded with a copy of the machine's installed packages.

Cause (attributed by counting, not by timing). Since f73682d5 the answer "which language names are available" (languages::known_language_names_in → Store::installed) reads every archive in the user's store and computes two content hashes for each. One process asks about 22 times, mostly through Config::warnings(). With seven packages one round costs about 0.33 s; the count per process was 357 archive parses for languages enable, 189 for index, 196 for a one-shot query. v0.41.48 shows the same figures with 7 and with 45 installed packages, so its cost does not grow with the store.

State of the fix. A first candidate reuses the parse result per process (keyed on the complete archive bytes; signature, trust, approval and enablement checks unchanged). It restores the old figures for the seven-package case, but still reads every installed archive on each of the 22 rounds and hashes each one once, so it remains 3.4 times slower than v0.41.48 with the large store. It went back for a second round with this requirement: the cost of startup, index and languages enable must not grow with packages that are installed but not used, and the gate counts that.

Why no gate saw it. Every CI runner and every test fixture has an empty or seven-package store, and the workspace test build compiles the parsers in. The gate for the fix therefore counts archive reads and hashes with extra unused packages installed, instead of bounding a time.

## The cost grows with the package store (measured 2026-11-12) The figures in the report were taken with only the seven first-party packages installed. With a store as a developer machine really has it (45 installed packages, 141 MiB, most of them not used by the project) the same steps cost: | step | v0.41.48 | master `3c8742bf` (= v0.41.49 … v0.41.51 behaviour) | first fix candidate | |---|---:|---:|---:| | `languages enable` (7 languages) | 13.6 s | 132.7 s | 16.1 s | | `index` | 3.6 s | 29.4 s | 5.5 s | | one-shot `query search_symbols` | 1.4 s | 17–19 s, the first call refused with `index_incomplete` | 4.7–5.1 s | Same machine, shipped build shape, fresh project and no daemon; the store was seeded with a copy of the machine's installed packages. **Cause (attributed by counting, not by timing).** Since `f73682d5` the answer "which language names are available" (`languages::known_language_names_in` → `Store::installed`) reads every archive in the user's store and computes two content hashes for each. One process asks about 22 times, mostly through `Config::warnings()`. With seven packages one round costs about 0.33 s; the count per process was 357 archive parses for `languages enable`, 189 for `index`, 196 for a one-shot query. v0.41.48 shows the same figures with 7 and with 45 installed packages, so its cost does not grow with the store. **State of the fix.** A first candidate reuses the parse result per process (keyed on the complete archive bytes; signature, trust, approval and enablement checks unchanged). It restores the old figures for the seven-package case, but still reads every installed archive on each of the 22 rounds and hashes each one once, so it remains 3.4 times slower than v0.41.48 with the large store. It went back for a second round with this requirement: the cost of startup, `index` and `languages enable` must not grow with packages that are installed but not used, and the gate counts that. **Why no gate saw it.** Every CI runner and every test fixture has an empty or seven-package store, and the workspace test build compiles the parsers in. The gate for the fix therefore counts archive reads and hashes with extra unused packages installed, instead of bounding a time.

buildagent referenced this issue from a commit

2026-11-13 01:03:24 +01:00

Merge lane r28: startup cost no longer grows with the package store (#581)

buildagent referenced this issue

2026-11-13 01:03:28 +01:00

v0.41.52: startup cost no longer grows with the package store (#581) #583

buildagent referenced this issue

2026-11-13 01:09:02 +01:00

Tool discovery and replies cost extra calls, while review and navigation still have gaps #521

buildagent referenced this issue from a commit

2026-11-13 12:22:38 +01:00

Merge PR #583: v0.41.52, startup no longer grows with the package store

buildagent referenced this issue

2026-11-13 12:54:04 +01:00

After a daemon restart a session can refuse every filter as "daemon predates the filter", and calls during the restart are refused instead of waiting #584

buildagent commented

2026-11-13 13:06:46 +01:00

Author

Member

Released in v0.41.52 (7fc7fb20, release run 8656, 15 assets). Verified on the installed Linux x86_64 binaries (code-index 0.41.52 (7fc7fb20)):

Steps of the release smoke, fresh project, no daemon running, seconds. The machine was loaded by other builds during the measurement (load 8 to 19), both releases alike.

build	package store	enable 7 languages	index	list	first query	second query
v0.41.52	7 bundled	14.2	3.7	0.8	1.7	1.6
v0.41.52	45 packages (141 MiB, copy of this machine's store)	13.8	3.5	0.7	1.7	1.8
v0.41.50	7 bundled	26.2	9.5	1.3	8.8	8.8
v0.41.50	45 packages	131.9	55.9	4.2	19.6, refused `index_incomplete`	17.6

The cost no longer depends on how many packages are installed.

Windows archive smoke of the release run (the step that stopped v0.41.51), compared with the v0.41.50 release run 8553: enable 20.0 s (was about 26.7 s), index 6.6 s and list 0.9 s (were about 11 s together), query 3.9 s without a retry (was about 9.8 s against a budget of 10 s). The script now prints each step's time, so the next release run can be compared directly.

Not covered: nothing measured on Windows with a large package store; the Windows figures are the 7-package smoke only.

Released in [v0.41.52](https://git.h-dv.de/h-dv/code-index/releases/tag/v0.41.52) (`7fc7fb20`, release run 8656, 15 assets). Verified on the installed Linux x86_64 binaries (`code-index 0.41.52 (7fc7fb20)`): Steps of the release smoke, fresh project, no daemon running, seconds. The machine was loaded by other builds during the measurement (load 8 to 19), both releases alike. | build | package store | enable 7 languages | index | list | first query | second query | | :-- | :-- | --: | --: | --: | --: | --: | | v0.41.52 | 7 bundled | 14.2 | 3.7 | 0.8 | 1.7 | 1.6 | | v0.41.52 | 45 packages (141 MiB, copy of this machine's store) | 13.8 | 3.5 | 0.7 | 1.7 | 1.8 | | v0.41.50 | 7 bundled | 26.2 | 9.5 | 1.3 | 8.8 | 8.8 | | v0.41.50 | 45 packages | 131.9 | 55.9 | 4.2 | 19.6, refused `index_incomplete` | 17.6 | The cost no longer depends on how many packages are installed. Windows archive smoke of the release run (the step that stopped v0.41.51), compared with the v0.41.50 release run 8553: enable 20.0 s (was about 26.7 s), index 6.6 s and list 0.9 s (were about 11 s together), query 3.9 s without a retry (was about 9.8 s against a budget of 10 s). The script now prints each step's time, so the next release run can be compared directly. Not covered: nothing measured on Windows with a large package store; the Windows figures are the 7-package smoke only.

buildagent closed this issue

2026-11-13 13:06:46 +01:00

buildagent referenced this issue

2026-11-13 13:07:19 +01:00

After a daemon restart a session can refuse every filter as "daemon predates the filter", and calls during the restart are refused instead of waiting #584

buildagent referenced this issue

2026-11-13 14:22:51 +01:00

After a daemon restart a session can refuse every filter as "daemon predates the filter", and calls during the restart are refused instead of waiting #584

buildagent referenced this issue

2026-11-13 15:02:41 +01:00

The nightly runs have been red on 11 of 13 completed runs since 2026-11-06 and nothing reports it: overhead budgets, two intermittent startup failures, a step-guard cascade #582

buildagent referenced this issue