PERF: every Markdown change re-indexes every Note (Notes import is O(n²); 155 ms server CPU per Note at 10k)

kayg commented

2026-09-30 08:04:37 +00:00

Owner

Problem

Every batch of .md change events makes the Notes plugin re-read and re-index every Note of the User. A Markdown import is therefore O(n²), and a single edit in a large Home costs work proportional to the whole Notes library.

Found by the #367 perf round on the perf-test VM (4 vCPU, 7.7 GiB; release build of dev at 369ab6a2f; load < 1 at start, /root/perf.lock held).

Measurements

Profile	Result
10k Markdown Notes via Tus (`notes-10k`)	1,069.7 s upload; p50 104.3 ms, p95 187.0 ms; 1,547.6 server CPU-s (155 ms per Note); server not idle at the end of the wait
Same import, server thread CPU	`tokio-rt-worker` 791 s, `sqlx-sqlite-wor` 676 s
10k plain `.txt` files for comparison (`files-50k`, first 10k)	sqlite 85.7 CPU-s (8.6 ms per file)
3,000-Note import with `RUST_LOG=sqlx::query=debug` (11 min)	277,476 calls of `store::index` (≈ 92 per Note); 7.35 M statements; 179 s of SQL time
`perf` 60 s samples at ~1.5k and ~3.5k Notes	sqlite share 20.7% → 35.4% of samples (`sqlite3BtreeNext`, `RecordCompare`); 63% of samples in the sqlite worker thread

Top statements by total time in the 3,000-Note trace:

Total s	Calls	Statement
114.5	277,476	`SELECT match_key FROM note_link_target_keys WHERE user_id=? AND path=?`
5.9	277,476	`INSERT INTO note_items … ON CONFLICT … DO UPDATE`
4.9	554,952	`INSERT OR IGNORE INTO note_link_target_keys …`
4.0	416,089	`SELECT uid,etag FROM reminder_resources WHERE user_id=? AND source=?`
3.7	416,089	`DELETE FROM task_items WHERE user_id=? AND source=?`

Cause

crates/plugins/notes/src/lib.rs (event loop near line 1420): for each 200 ms batch of fs events, if any path ends in .md, it calls reconcile_user, which runs tasks_store::reconcile_user + store::reconcile_user. Both tasks_store::reconcile_user (tasks_store.rs ~line 671) and store::reconcile_user (store.rs ~line 1682) call store::scan (read every Note file from disk) and then store::index for every Note, so each batch indexes every Note twice. An import of n Notes makes about n/k batches, each re-indexing all Notes so far.

Secondary: SELECT match_key FROM note_link_target_keys WHERE user_id=? AND path=? averages 0.41 ms per call although note_link_target_keys_path(user_id, path) exists; check its plan once the call count is fixed.

Suggested direction (not decided)

Index only the changed paths from the batch (the event already carries them), and keep the full reconcile_user for lag/startup only. Keep the link-health and task projections correct for renames and deletes (the reason for the full pass should be recorded in the code comment).

Repro

python3 tests/perf/upload_scale.py --server <release server> --checkpoints 3000 --folder Notes --extension md --no-model-wait --data-root target/tmp --json /tmp/n.json with RUST_LOG=warn,sqlx::query=debug, then count store::index statements (INSERT INTO note_items) in the server log: expect ≈ 3,000, observed ≈ 277,000.

Decision rule for the fix (from #367): keep it only if Notes-import server CPU drops ≥ 10% (median of 5 interleaved A/B runs) with no other tracked metric > 3% worse.

## Problem Every batch of `.md` change events makes the Notes plugin re-read and re-index **every Note of the User**. A Markdown import is therefore O(n²), and a single edit in a large Home costs work proportional to the whole Notes library. Found by the #367 perf round on the perf-test VM (4 vCPU, 7.7 GiB; release build of `dev` at `369ab6a2f`; load < 1 at start, `/root/perf.lock` held). ## Measurements | Profile | Result | |---|---| | 10k Markdown Notes via Tus (`notes-10k`) | 1,069.7 s upload; p50 104.3 ms, p95 187.0 ms; **1,547.6 server CPU-s (155 ms per Note)**; server not idle at the end of the wait | | Same import, server thread CPU | `tokio-rt-worker` 791 s, `sqlx-sqlite-wor` 676 s | | 10k plain `.txt` files for comparison (`files-50k`, first 10k) | sqlite 85.7 CPU-s (8.6 ms per file) | | 3,000-Note import with `RUST_LOG=sqlx::query=debug` (11 min) | **277,476 calls of `store::index`** (≈ 92 per Note); 7.35 M statements; 179 s of SQL time | | `perf` 60 s samples at ~1.5k and ~3.5k Notes | sqlite share 20.7% → 35.4% of samples (`sqlite3BtreeNext`, `RecordCompare`); 63% of samples in the sqlite worker thread | Top statements by total time in the 3,000-Note trace: | Total s | Calls | Statement | |---:|---:|---| | 114.5 | 277,476 | `SELECT match_key FROM note_link_target_keys WHERE user_id=? AND path=?` | | 5.9 | 277,476 | `INSERT INTO note_items … ON CONFLICT … DO UPDATE` | | 4.9 | 554,952 | `INSERT OR IGNORE INTO note_link_target_keys …` | | 4.0 | 416,089 | `SELECT uid,etag FROM reminder_resources WHERE user_id=? AND source=?` | | 3.7 | 416,089 | `DELETE FROM task_items WHERE user_id=? AND source=?` | ## Cause `crates/plugins/notes/src/lib.rs` (event loop near line 1420): for each 200 ms batch of `fs` events, if any path ends in `.md`, it calls `reconcile_user`, which runs `tasks_store::reconcile_user` + `store::reconcile_user`. Both `tasks_store::reconcile_user` (`tasks_store.rs` ~line 671) and `store::reconcile_user` (`store.rs` ~line 1682) call `store::scan` (read every Note file from disk) and then `store::index` for every Note, so each batch indexes every Note twice. An import of n Notes makes about n/k batches, each re-indexing all Notes so far. Secondary: `SELECT match_key FROM note_link_target_keys WHERE user_id=? AND path=?` averages 0.41 ms per call although `note_link_target_keys_path(user_id, path)` exists; check its plan once the call count is fixed. ## Suggested direction (not decided) Index only the changed paths from the batch (the event already carries them), and keep the full `reconcile_user` for lag/startup only. Keep the link-health and task projections correct for renames and deletes (the reason for the full pass should be recorded in the code comment). ## Repro `python3 tests/perf/upload_scale.py --server <release server> --checkpoints 3000 --folder Notes --extension md --no-model-wait --data-root target/tmp --json /tmp/n.json` with `RUST_LOG=warn,sqlx::query=debug`, then count `store::index` statements (`INSERT INTO note_items`) in the server log: expect ≈ 3,000, observed ≈ 277,000. Decision rule for the fix (from #367): keep it only if Notes-import server CPU drops ≥ 10% (median of 5 interleaved A/B runs) with no other tracked metric > 3% worse.

kayg referenced this issue

2026-09-30 08:46:05 +00:00

PERF ROUND: benchmark + optimise average and worst-case CPU/memory (after current merges) #367

kayg commented

2026-09-30 13:56:00 +00:00

Author

Owner

Starting #494 on branch job/perf-494. Worktree base SHA: 6c87f5ff9442cd658572139bc536d018fd5222a4 (the current origin/dev is cd3cea757508d9f581d00fb7d5d7973fbc0a75fd; I will merge it once before final gates as requested).

Starting #494 on branch `job/perf-494`. Worktree base SHA: `6c87f5ff9442cd658572139bc536d018fd5222a4` (the current `origin/dev` is `cd3cea757508d9f581d00fb7d5d7973fbc0a75fd`; I will merge it once before final gates as requested).

kayg commented

2026-09-30 14:08:17 +00:00

Author

Owner

Confirmed the hot path in crates/plugins/notes/src/lib.rs: the fs watcher batches paths for 200 ms, then any .md path calls reconcile_user; that wrapper runs both full tasks_store::reconcile_user and store::reconcile_user, and each scans Home Markdown and indexes each Note. crates/calternal-server/src/wire.rs also calls calternal_plugin_notes::adopt_change before publishing the fs event, so the event path re-indexes the changed Note after that direct adoption. I am replacing the batch full scan with changed-path projection and keeping full reconciliation for startup/lag recovery.

Confirmed the hot path in `crates/plugins/notes/src/lib.rs`: the `fs` watcher batches paths for 200 ms, then any `.md` path calls `reconcile_user`; that wrapper runs both full `tasks_store::reconcile_user` and `store::reconcile_user`, and each scans Home Markdown and indexes each Note. `crates/calternal-server/src/wire.rs` also calls `calternal_plugin_notes::adopt_change` before publishing the `fs` event, so the event path re-indexes the changed Note after that direct adoption. I am replacing the batch full scan with changed-path projection and keeping full reconciliation for startup/lag recovery.

kayg commented

2026-09-30 14:49:05 +00:00

Author

Owner

A projection dependency surfaced while replacing the full pass: store::index_calendar_logs checks Task frontmatter links against task_items. Updating only the changed Task can leave a linked Daily note showing a stale Calendar Task attachment when the file stops being a Task. I added a regression that observes the stale Notes/linked-task.md attachment before the fix and the empty attachment list after it. The incremental path now refreshes only linked Daily notes when Task membership changes; ordinary status edits do not re-index referrers.

A projection dependency surfaced while replacing the full pass: `store::index_calendar_logs` checks Task frontmatter links against `task_items`. Updating only the changed Task can leave a linked Daily note showing a stale Calendar Task attachment when the file stops being a Task. I added a regression that observes the stale `Notes/linked-task.md` attachment before the fix and the empty attachment list after it. The incremental path now refreshes only linked Daily notes when Task membership changes; ordinary status edits do not re-index referrers.

kayg commented

2026-09-30 15:51:24 +00:00

Author

Owner

Perf setup finding: the perf VM accepted flock -n /root/perf.lock, but /mnt/hdd/targets/release-shared is absent on that host (ls returned “No such file or directory”). I built this branch's release server on the build host and will transfer that binary to the VM for the locked measurement; no compilation will run on the VM.

Perf setup finding: the perf VM accepted `flock -n /root/perf.lock`, but `/mnt/hdd/targets/release-shared` is absent on that host (`ls` returned “No such file or directory”). I built this branch's release server on the build host and will transfer that binary to the VM for the locked measurement; no compilation will run on the VM.

kayg commented

2026-09-30 16:11:30 +00:00

Author

Owner

10k Notes profile on the perf VM, using the same tests/perf/upload_scale.py probe as #494 (one patched run, commit 7d765126c): 991.0 s upload time, p50 97.98 ms, p95 221.26 ms, server CPU 352.4 s, mean RSS 244,795,610 bytes, and peak RSS 327,462,912 bytes. The 10k search probe found the last Note. The run's load average was 0.07 before and 2.29 after.

Against the issue's recorded baseline (1069.7 s, p50 104.3 ms, p95 187.0 ms, server CPU 1547.6 s), this run used 77.2% less server CPU and finished 7.4% sooner; p50 improved 6.1%, while p95 was 18.3% higher. This is one patched run, not a five-run interleaved A/B median. The raw result and comparison are being added under docs/perf/runs/.

10k Notes profile on the perf VM, using the same `tests/perf/upload_scale.py` probe as #494 (one patched run, commit `7d765126c`): 991.0 s upload time, p50 97.98 ms, p95 221.26 ms, server CPU 352.4 s, mean RSS 244,795,610 bytes, and peak RSS 327,462,912 bytes. The 10k search probe found the last Note. The run's load average was 0.07 before and 2.29 after. Against the issue's recorded baseline (1069.7 s, p50 104.3 ms, p95 187.0 ms, server CPU 1547.6 s), this run used 77.2% less server CPU and finished 7.4% sooner; p50 improved 6.1%, while p95 was 18.3% higher. This is one patched run, not a five-run interleaved A/B median. The raw result and comparison are being added under `docs/perf/runs/`.

kayg commented

2026-09-30 16:16:06 +00:00

Author

Owner

Finished. Branch: job/perf-494. HEAD: c927e614e37b157ed133e32b15a2967a25a76b4d.

Implemented incremental Markdown reconciliation. A batch indexes changed Notes and only refreshes linked Daily notes when Task membership changes. Startup and lag recovery still use full reconciliation. Added a regression test that observes one Note projection update for one fs change, plus a test that checks the Daily note attachment after a file stops being a Task.

Files: crates/plugins/notes/src/lib.rs, crates/plugins/notes/src/store.rs, bench/notes-import.sh, docs/perf/README.md, docs/perf/runs/2026-09-30-issue-494-notes-import.md, and docs/perf/runs/2026-09-30T155312Z-7d765126c-notes-10k.json.

One 10k perf VM run on the same sequential upload probe as the issue baseline: 991.0 s upload time, p50 97.98 ms, p95 221.26 ms, server CPU 352.4 s, mean RSS 244,795,610 bytes, peak RSS 327,462,912 bytes. The issue baseline is 1069.7 s, p50 104.3 ms, p95 187.0 ms, server CPU 1547.6 s. Server CPU fell 77.2%; p95 rose 18.3%. The last Note was searchable. Load average (1/5/15 minute) changed from 0.07/0.09/0.11 to 2.29/2.41/1.75.

Gates (verbatim output):

cargo fmt --check: no output; exit 0.
cargo clippy -p calternal-plugin-notes --all-targets -- -D warnings: Finished \dev` profile [unoptimized + debuginfo] target(s) in 10m 43s`.
cargo test -p calternal-plugin-notes: test result: ok. 128 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 195.65s; integration: test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.52s; doc tests: test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s.
bash -n bench/notes-import.sh and git diff --check: no output; exit 0.
cargo clean: Removed 14124 files, 5.0GiB total.

Known gap: this is one patched run, not the issue's five-run interleaved A/B median. The perf VM did not have /mnt/hdd/targets/release-shared, so I built this commit's release server on the build host and copied it to the VM; no compilation ran on the VM. No routes or APIs changed, so no adversarial API round was needed. Decision outside DESIGN: when the shared perf artifact is missing on the VM, transfer the branch-built release binary from the build host and still run the measured profile under the VM lock.

Finished. Branch: `job/perf-494`. HEAD: `c927e614e37b157ed133e32b15a2967a25a76b4d`. Implemented incremental Markdown reconciliation. A batch indexes changed Notes and only refreshes linked Daily notes when Task membership changes. Startup and lag recovery still use full reconciliation. Added a regression test that observes one Note projection update for one fs change, plus a test that checks the Daily note attachment after a file stops being a Task. Files: `crates/plugins/notes/src/lib.rs`, `crates/plugins/notes/src/store.rs`, `bench/notes-import.sh`, `docs/perf/README.md`, `docs/perf/runs/2026-09-30-issue-494-notes-import.md`, and `docs/perf/runs/2026-09-30T155312Z-7d765126c-notes-10k.json`. One 10k perf VM run on the same sequential upload probe as the issue baseline: 991.0 s upload time, p50 97.98 ms, p95 221.26 ms, server CPU 352.4 s, mean RSS 244,795,610 bytes, peak RSS 327,462,912 bytes. The issue baseline is 1069.7 s, p50 104.3 ms, p95 187.0 ms, server CPU 1547.6 s. Server CPU fell 77.2%; p95 rose 18.3%. The last Note was searchable. Load average (1/5/15 minute) changed from 0.07/0.09/0.11 to 2.29/2.41/1.75. Gates (verbatim output): - `cargo fmt --check`: no output; exit 0. - `cargo clippy -p calternal-plugin-notes --all-targets -- -D warnings`: `Finished \`dev\` profile [unoptimized + debuginfo] target(s) in 10m 43s`. - `cargo test -p calternal-plugin-notes`: `test result: ok. 128 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 195.65s`; integration: `test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.52s`; doc tests: `test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s`. - `bash -n bench/notes-import.sh` and `git diff --check`: no output; exit 0. - `cargo clean`: `Removed 14124 files, 5.0GiB total`. Known gap: this is one patched run, not the issue's five-run interleaved A/B median. The perf VM did not have `/mnt/hdd/targets/release-shared`, so I built this commit's release server on the build host and copied it to the VM; no compilation ran on the VM. No routes or APIs changed, so no adversarial API round was needed. Decision outside DESIGN: when the shared perf artifact is missing on the VM, transfer the branch-built release binary from the build host and still run the measured profile under the VM lock.

kayg referenced this issue from a commit

2026-09-30 16:20:34 +00:00

Record Notes import performance for #494

kayg referenced this issue from a commit

2026-10-01 00:12:51 +00:00

Merge performance profile and comparison reporting (#494)

kayg referenced this issue

2026-10-01 01:34:15 +00:00

PERF: verification batch on the perf VM for finished branches (#498 #423 #494 #527 #530) #563

kayg commented

2026-10-01 09:17:53 +00:00

Author