kayg/calternal

Watch

Fork 0

Startup after an upgrade blocks the listener for ~7 minutes (backfills before bind) #1011

New issue

Open

opened 2026-10-03 14:26:26 +00:00 by kayg · 4 comments

kayg commented

2026-10-03 14:26:26 +00:00

Owner

Found in the 7a production deploy (2026-10-03)

After upgrading from c4a61e8cf to c82b9aca1 (13 migrations), the server took about 7 minutes before /healthz answered. The log showed embedding/semantic vector inserts (ort, slow-statement warnings) during that time; the listener was not yet bound. A deploy must not make the site unavailable for minutes.

Fix

Bind the HTTP listener and answer /healthz (and serve the app shell with a calm 'catching up' state if needed) as soon as migrations finish; run backfills, reindex, embeddings and reconcile in the background with bounded priority. Measure: time from process start to first 200 on /healthz and to first interactive page on a production-sized copy (synthetic, HDD path) for an upgrade with backfills; target < 15 s. Add the measurement to bench/ and a regression guard.

## Found in the 7a production deploy (2026-10-03) After upgrading from c4a61e8cf to c82b9aca1 (13 migrations), the server took about 7 minutes before /healthz answered. The log showed embedding/semantic vector inserts (ort, slow-statement warnings) during that time; the listener was not yet bound. A deploy must not make the site unavailable for minutes. ## Fix Bind the HTTP listener and answer /healthz (and serve the app shell with a calm 'catching up' state if needed) as soon as migrations finish; run backfills, reindex, embeddings and reconcile in the background with bounded priority. Measure: time from process start to first 200 on /healthz and to first interactive page on a production-sized copy (synthetic, HDD path) for an upgrade with backfills; target < 15 s. Add the measurement to bench/ and a regression guard.

kayg commented

2026-10-04 03:18:53 +00:00

Author

Owner

Started startup-1011 on branch job/startup-1011, base f2f8491ff5c76ab28f140c964542c97362e6b119 (origin/dev). Investigating work before HTTP bind. No pushes or deploys.

Started startup-1011 on branch `job/startup-1011`, base `f2f8491ff5c76ab28f140c964542c97362e6b119` (origin/dev). Investigating work before HTTP bind. No pushes or deploys.

kayg commented

2026-10-04 03:24:17 +00:00

Author

Owner

Finding: build_live_app awaited calternal_plugin_notes::recover, which scanned each Home and ran three Daily note metadata migrations before bind. Their checked writes queue semantic changes through sync_homes and the change bridges. SemanticIndexer::start also awaited derived schema revision cleanup and started model/index workers before bind. The existing post-bind gate covered only Files, Tags and keyword Search reconciliation. Fix separates durable Notes intent recovery from optional backfills, defers semantic schema/workers, and starts the job worker on the existing low-priority post-bind runtime with two blocking threads. A locked-Home HTTP regression will prove health and the app shell stay available while backfills wait.

Decisions: keep source-write recovery and security initialization before HTTP. Serve the existing real views during derived catch-up; semantic Search falls back to keyword results until its schema is ready. No new startup banner is needed.

Finding: `build_live_app` awaited `calternal_plugin_notes::recover`, which scanned each Home and ran three Daily note metadata migrations before bind. Their checked writes queue semantic changes through `sync_homes` and the change bridges. `SemanticIndexer::start` also awaited derived schema revision cleanup and started model/index workers before bind. The existing post-bind gate covered only Files, Tags and keyword Search reconciliation. Fix separates durable Notes intent recovery from optional backfills, defers semantic schema/workers, and starts the job worker on the existing low-priority post-bind runtime with two blocking threads. A locked-Home HTTP regression will prove health and the app shell stay available while backfills wait. Decisions: keep source-write recovery and security initialization before HTTP. Serve the existing real views during derived catch-up; semantic Search falls back to keyword results until its schema is ready. No new startup banner is needed.

kayg commented

2026-10-04 03:53:20 +00:00

Author

Owner

Progress: Notes recovery/backfill split committed as 7f7c84144; deferred semantic startup as db624a37c; post-bind background runtime and HTTP regression as 7f2d84254. Notes tests: 187 passed plus 1 integration test; embed tests: 38 passed; server tests: 162 passed. The explicit locked-Home HTTP regression passed in 2.23 s.

Evidence: the existing shared release on perf-test did not open its HTTP listener within the 180 s preparation bound after adding the synthetic Home (656 Daily notes × 12 Log entries, 2,000 Notes, 10,000 text files). The run held /root/perf.lock and used /srv/hdd-emu. It stopped and removed its test state. This is an old-release reproduction, not an acceptance measurement of the fix. The new shared release measurement remains for the merge round under the verification policy.

Final priority detail: SQLx starts a separate native SQLite worker when its first connection opens. The deferred semantic constructor now creates a lazy pool, so its first worker starts on the low-priority post-bind runtime. A regression asserts that no semantic SQLite file exists before that phase. No dependency versions changed.

Progress: Notes recovery/backfill split committed as `7f7c84144`; deferred semantic startup as `db624a37c`; post-bind background runtime and HTTP regression as `7f2d84254`. Notes tests: 187 passed plus 1 integration test; embed tests: 38 passed; server tests: 162 passed. The explicit locked-Home HTTP regression passed in 2.23 s. Evidence: the existing shared release on perf-test did not open its HTTP listener within the 180 s preparation bound after adding the synthetic Home (656 Daily notes × 12 Log entries, 2,000 Notes, 10,000 text files). The run held `/root/perf.lock` and used `/srv/hdd-emu`. It stopped and removed its test state. This is an old-release reproduction, not an acceptance measurement of the fix. The new shared release measurement remains for the merge round under the verification policy. Final priority detail: SQLx starts a separate native SQLite worker when its first connection opens. The deferred semantic constructor now creates a lazy pool, so its first worker starts on the low-priority post-bind runtime. A regression asserts that no semantic SQLite file exists before that phase. No dependency versions changed.

kayg commented

2026-10-04 04:10:26 +00:00

Author

Owner

READY FOR MERGE: yes

Head: 483e6abc6e9db308b082a8f0a8b7f2548a7574d0. Branch: job/startup-1011. Base: f2f8491ff5c76ab28f140c964542c97362e6b119. The required fetch and merge of origin/dev reported Already up to date. Five atomic commits. No push or deploy.

Built

HTTP startup now completes mandatory migrations and source-write recovery, then binds before optional upgrade work. Notes backfills, semantic schema cleanup, model loading, embeddings and job startup run behind the existing post-bind gate. The background runtime uses the existing nice=10 and idle I/O priority with two blocking threads. The semantic pool is lazy so its native SQLite thread also starts with that priority. The runtime remains alive for normal jobs and has a shutdown hook.

Regression tests prove that a locked Home cannot prevent health, readiness or the app shell from serving. They then release the lock and check backfill completion and retained source text. Separate tests check that semantic startup opens no SQLite file or model before its explicit phase and that Notes recovery does not run backfills.

The bench profile uses the perf VM lock and HDD I/O scope. It primes real projections, resets backfill markers offline, freezes the binary, measures health and keyboard interaction, and sends a 64-request health burst. It reports p50/p95, CPU and RSS. Its guard requires both milestones to be less than 15 seconds. An older release can prime SQL migrations too.

Files

bench/startup-1011.md
bench/startup-1011.mjs
bench/startup-1011.test.mjs
bench/tab-switch.mjs
crates/calternal-embed/src/lib.rs
crates/calternal-embed/src/store.rs
crates/calternal-embed/src/user_store.rs
crates/calternal-server/src/main.rs
crates/calternal-server/src/wire.rs
crates/plugins/notes/src/lib.rs

Gates (verbatim summary output)

cargo fmt --check: exit 0, no output.

cargo clippy -p calternal-plugin-notes --all-targets -- -D warnings:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 12.16s

cargo test -p calternal-plugin-notes -- --test-threads=4:

test result: ok. 187 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 150.68s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.50s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

cargo clippy -p calternal-embed --all-targets -- -D warnings:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 5.82s

cargo test -p calternal-embed -- --test-threads=4:

test result: ok. 38 passed; 0 failed; 4 ignored; 0 measured; 0 filtered out; finished in 24.35s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

cargo clippy -p calternal-server --all-targets -- -D warnings:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 24.47s

cargo test -p calternal-server -- --test-threads=4:

test result: ok. 162 passed; 0 failed; 6 ignored; 0 measured; 0 filtered out; finished in 17.51s

The server suite's process-isolated wrapper runs the locked-Home HTTP regression, despite its individual ignored marker. Its separate focused run also passed:

test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 167 filtered out; finished in 2.23s

bun test bench/startup-1011.test.mjs bench/tab-switch.test.mjs:

bun test v1.4.2 (744846f84)

bench/tab-switch.test.mjs:
(pass) pending Calendar selection cannot paint the previous Photos route [0.09ms]
(pass) request timeout diagnostics redact credential headers, including ANSI lines [0.29ms]

bench/startup-1011.test.mjs:
(pass) both startup milestones must be finite, non-negative and under 15 seconds [0.27ms]
(pass) tail startup samples remain visible in the p95 result [0.34ms]

 4 pass
 0 fail
 15 expect() calls
Ran 4 tests across 2 files. [87.00ms]

The production web build passed before the server gates. No web source changed, so no web check or screenshot set was required. No existing test expectations changed. Doc comments of all changed files were read again before this report.

Performance evidence

The available shared release predates the fix (binary SHA-256 bd8c76bf064fd1c7365af5f0e96f71ebf1cd4e6cebd481d51dd82f5adc088dc3). All measured runs held /root/perf.lock and used /srv/hdd-emu.

Production-sized fixture: 656 Daily notes with 7,872 Log entries, 2,000 other Notes and 10,000 text files. The old release did not bind within the 180-second preparation bound. This is a lower-bound reproduction, not a completed acceptance measurement.
Small control, one sample: 10 Daily notes, 10 other Notes and 100 text files. Health: 12,129.529 ms. Interactive Files and Cmd+K: 17,004.898 ms. The 64-request health burst: 99.590 ms, all 200. Process CPU: 1.55 s. RSS: 167,317,504 bytes. Load inside the lock: 0.01 / 0.41 / 0.58. The old release fails the interactive budget even at this size.
docs/perf/baseline.json has no startup metric. These old-release results are a separate baseline. The browser runs on the build host; reported startup includes SSH dispatch and browser waits.

UX gaps closed

Health, readiness and the real app shell stay available while Notes upgrade backfills wait. Semantic Search falls back to keyword Search while its schema starts. No new prompt or banner was added.

Known gaps / UX gaps left

The fixed shared release's production-sized and largest-Home measurements remain for the merge round. Per-branch policy excludes release builds and full adversarial/e2e suites from this job. The old-release baseline is not evidence that this head meets the 15-second production target. A semantic schema initialization error is logged and leaves keyword Search available; semantic initialization retries on restart.

Decisions

Keep security initialization, snapshots and durable intent recovery before HTTP. Deferring interrupted source writes could expose inconsistent identities.
Use the existing views during catch-up. A new catching-up banner is not needed for the change.
Keep the background runtime alive after its startup pass, and stop it after HTTP and live Notes drain. Bound its blocking pool to two threads and inherit priority for semantic SQLite startup.
Keep the existing eager Notes recovery and semantic start APIs for other callers. Add the explicit phases used by the server; do not change those callers' behavior.

For the merge round

After building the combined release on the build host and copying it to the VM's shared release path, run:

TAB_SWITCH_VM_LOCK_WAIT_SECONDS=1 STARTUP_RUNS=3 bun bench/startup-1011.mjs
STARTUP_DAILY_NOTES=6560 STARTUP_NOTES=5000 STARTUP_FILES=100000 STARTUP_RUNS=3 TAB_SWITCH_VM_LOCK_WAIT_SECONDS=1 bun bench/startup-1011.mjs

Set CALTERNAL_STARTUP_FROM_BIN to the previous deployed release and CALTERNAL_STARTUP_MODEL_DIR to the pinned model directory on the perf VM. These runs must prove the health and interactive milestones are under 15 seconds during a real migration/backfill upgrade, and report the worst-case burst. The script owns the VM lock. Do not compile on the VM.

The combined branch also runs its standard full web and real-server regression round:

(cd apps/web && bun run check && bun run test -- --maxWorkers=2 && bun run test:e2e)
bash tests/adversarial/run.sh

These must check cross-Plugin consistency and live writes while backfills run, including restart recovery. No new endpoint or API contract was added.

Cleanup

cargo clean:

     Removed 17371 files, 8.3GiB total

Removed apps/web/build and apps/web/.svelte-kit. The worktree is clean. No review artifacts were committed. Local logs and control results remain under artifacts/.

READY FOR MERGE: yes Head: `483e6abc6e9db308b082a8f0a8b7f2548a7574d0`. Branch: `job/startup-1011`. Base: `f2f8491ff5c76ab28f140c964542c97362e6b119`. The required fetch and merge of origin/dev reported `Already up to date.` Five atomic commits. No push or deploy. ## Built HTTP startup now completes mandatory migrations and source-write recovery, then binds before optional upgrade work. Notes backfills, semantic schema cleanup, model loading, embeddings and job startup run behind the existing post-bind gate. The background runtime uses the existing nice=10 and idle I/O priority with two blocking threads. The semantic pool is lazy so its native SQLite thread also starts with that priority. The runtime remains alive for normal jobs and has a shutdown hook. Regression tests prove that a locked Home cannot prevent health, readiness or the app shell from serving. They then release the lock and check backfill completion and retained source text. Separate tests check that semantic startup opens no SQLite file or model before its explicit phase and that Notes recovery does not run backfills. The bench profile uses the perf VM lock and HDD I/O scope. It primes real projections, resets backfill markers offline, freezes the binary, measures health and keyboard interaction, and sends a 64-request health burst. It reports p50/p95, CPU and RSS. Its guard requires both milestones to be less than 15 seconds. An older release can prime SQL migrations too. ## Files - `bench/startup-1011.md` - `bench/startup-1011.mjs` - `bench/startup-1011.test.mjs` - `bench/tab-switch.mjs` - `crates/calternal-embed/src/lib.rs` - `crates/calternal-embed/src/store.rs` - `crates/calternal-embed/src/user_store.rs` - `crates/calternal-server/src/main.rs` - `crates/calternal-server/src/wire.rs` - `crates/plugins/notes/src/lib.rs` ## Gates (verbatim summary output) `cargo fmt --check`: exit 0, no output. `cargo clippy -p calternal-plugin-notes --all-targets -- -D warnings`: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 12.16s ``` `cargo test -p calternal-plugin-notes -- --test-threads=4`: ``` test result: ok. 187 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 150.68s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.50s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` `cargo clippy -p calternal-embed --all-targets -- -D warnings`: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 5.82s ``` `cargo test -p calternal-embed -- --test-threads=4`: ``` test result: ok. 38 passed; 0 failed; 4 ignored; 0 measured; 0 filtered out; finished in 24.35s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` `cargo clippy -p calternal-server --all-targets -- -D warnings`: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 24.47s ``` `cargo test -p calternal-server -- --test-threads=4`: ``` test result: ok. 162 passed; 0 failed; 6 ignored; 0 measured; 0 filtered out; finished in 17.51s ``` The server suite's process-isolated wrapper runs the locked-Home HTTP regression, despite its individual ignored marker. Its separate focused run also passed: ``` test wire::tests::startup_serves_http_while_upgrade_backfills_wait ... ok test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 167 filtered out; finished in 2.23s ``` `bun test bench/startup-1011.test.mjs bench/tab-switch.test.mjs`: ``` bun test v1.4.2 (744846f84) bench/tab-switch.test.mjs: (pass) pending Calendar selection cannot paint the previous Photos route [0.09ms] (pass) request timeout diagnostics redact credential headers, including ANSI lines [0.29ms] bench/startup-1011.test.mjs: (pass) both startup milestones must be finite, non-negative and under 15 seconds [0.27ms] (pass) tail startup samples remain visible in the p95 result [0.34ms] 4 pass 0 fail 15 expect() calls Ran 4 tests across 2 files. [87.00ms] ``` The production web build passed before the server gates. No web source changed, so no web check or screenshot set was required. No existing test expectations changed. Doc comments of all changed files were read again before this report. ## Performance evidence The available shared release predates the fix (binary SHA-256 `bd8c76bf064fd1c7365af5f0e96f71ebf1cd4e6cebd481d51dd82f5adc088dc3`). All measured runs held `/root/perf.lock` and used `/srv/hdd-emu`. - Production-sized fixture: 656 Daily notes with 7,872 Log entries, 2,000 other Notes and 10,000 text files. The old release did not bind within the 180-second preparation bound. This is a lower-bound reproduction, not a completed acceptance measurement. - Small control, one sample: 10 Daily notes, 10 other Notes and 100 text files. Health: 12,129.529 ms. Interactive Files and Cmd+K: 17,004.898 ms. The 64-request health burst: 99.590 ms, all 200. Process CPU: 1.55 s. RSS: 167,317,504 bytes. Load inside the lock: 0.01 / 0.41 / 0.58. The old release fails the interactive budget even at this size. - `docs/perf/baseline.json` has no startup metric. These old-release results are a separate baseline. The browser runs on the build host; reported startup includes SSH dispatch and browser waits. ## UX gaps closed Health, readiness and the real app shell stay available while Notes upgrade backfills wait. Semantic Search falls back to keyword Search while its schema starts. No new prompt or banner was added. ## Known gaps / UX gaps left The fixed shared release's production-sized and largest-Home measurements remain for the merge round. Per-branch policy excludes release builds and full adversarial/e2e suites from this job. The old-release baseline is not evidence that this head meets the 15-second production target. A semantic schema initialization error is logged and leaves keyword Search available; semantic initialization retries on restart. ## Decisions - Keep security initialization, snapshots and durable intent recovery before HTTP. Deferring interrupted source writes could expose inconsistent identities. - Use the existing views during catch-up. A new catching-up banner is not needed for the change. - Keep the background runtime alive after its startup pass, and stop it after HTTP and live Notes drain. Bound its blocking pool to two threads and inherit priority for semantic SQLite startup. - Keep the existing eager Notes recovery and semantic start APIs for other callers. Add the explicit phases used by the server; do not change those callers' behavior. ## For the merge round After building the combined release on the build host and copying it to the VM's shared release path, run: ``` TAB_SWITCH_VM_LOCK_WAIT_SECONDS=1 STARTUP_RUNS=3 bun bench/startup-1011.mjs STARTUP_DAILY_NOTES=6560 STARTUP_NOTES=5000 STARTUP_FILES=100000 STARTUP_RUNS=3 TAB_SWITCH_VM_LOCK_WAIT_SECONDS=1 bun bench/startup-1011.mjs ``` Set `CALTERNAL_STARTUP_FROM_BIN` to the previous deployed release and `CALTERNAL_STARTUP_MODEL_DIR` to the pinned model directory on the perf VM. These runs must prove the health and interactive milestones are under 15 seconds during a real migration/backfill upgrade, and report the worst-case burst. The script owns the VM lock. Do not compile on the VM. The combined branch also runs its standard full web and real-server regression round: ``` (cd apps/web && bun run check && bun run test -- --maxWorkers=2 && bun run test:e2e) bash tests/adversarial/run.sh ``` These must check cross-Plugin consistency and live writes while backfills run, including restart recovery. No new endpoint or API contract was added. ## Cleanup `cargo clean`: ``` Removed 17371 files, 8.3GiB total ``` Removed `apps/web/build` and `apps/web/.svelte-kit`. The worktree is clean. No review artifacts were committed. Local logs and control results remain under `artifacts/`.

kayg referenced this issue

2026-10-04 06:15:11 +00:00

Daily Log projection rebuild did not run after the #998 upgrade on production #1033

kayg referenced this issue

2026-10-04 06:31:17 +00:00

Daily Log projection rebuild did not run after the #998 upgrade on production #1033

kayg referenced this issue

2026-10-04 06:31:25 +00:00

Expose Daily note Log parse state in the Index #998

kayg referenced this issue

2026-10-04 08:34:26 +00:00

Plan: merge order and conflicts for merge round 7b #867