Perf: task create serializes at ~0.4 s under a 24-request storm after search indexer merge

kayg commented

2026-09-24 18:46:02 +00:00

Owner

After the search-backend merge (cf996cb), tests/adversarial/run.sh round 1 reports Task storm 9..23 :: SLOW 5.1s → 9.9s status 201. The storm sends 24 POST /api/v1/notes/tasks from one user, 12 at a time. All requests succeed (no data loss, no 5xx). The latency grows linearly per request, so task creation is serialized (per-user lock_user) at about 0.4 s per create. On 41aa774 (before the merge) the same probe had 0 findings, but the machine was under heavy load in both runs (load average 30 on 8 cores; 9 cargo builds on one SSD), so the numbers are noisy.

Suspects:

The search indexer (crates/calternal-search/src/indexer.rs, flush_upserts) now indexes each daily-note log entry as its own document and runs a Tantivy commit() + reader.reload() + SQLite manifest transaction for every flush. That is fsync-heavy and competes with the notes plugin's temp→fsync→rename writes.
Any work done while holding the per-user notes lock (for example waiting on index or DB writes).

Do:

Measure on an idle machine: p50/p95 of a single task create and of the 24-request storm, on 41aa774 versus cf996cb. Quote the numbers.
If the indexer is the cause: coalesce commits (debounce ~250–500 ms, commit at most once per window), and never block the write path on indexing.
If the notes lock is the cause: shrink the critical section (compute outside the lock, hold it only for the read-modify-write of the file).
Budget: 24 concurrent task creates for one user complete in < 3 s total on a loaded box, with p95 single create < 150 ms idle. Keep the adversarial SLOW threshold as the regression gate.
Not a merge blocker (owner rule: performance issues are filed, not blocking), but fix it soon: it's on the capture path.

After the search-backend merge (`cf996cb`), `tests/adversarial/run.sh` round 1 reports `Task storm 9..23 :: SLOW 5.1s → 9.9s status 201`. The storm sends 24 `POST /api/v1/notes/tasks` from one user, 12 at a time. All requests succeed (no data loss, no 5xx). The latency grows linearly per request, so task creation is serialized (per-user `lock_user`) at about 0.4 s per create. On `41aa774` (before the merge) the same probe had 0 findings, but the machine was under heavy load in both runs (load average 30 on 8 cores; 9 cargo builds on one SSD), so the numbers are noisy. Suspects: - The search indexer (`crates/calternal-search/src/indexer.rs`, `flush_upserts`) now indexes each daily-note log entry as its own document and runs a Tantivy `commit()` + `reader.reload()` + SQLite manifest transaction for every flush. That is fsync-heavy and competes with the notes plugin's temp→fsync→rename writes. - Any work done while holding the per-user notes lock (for example waiting on index or DB writes). Do: 1. Measure on an idle machine: p50/p95 of a single task create and of the 24-request storm, on `41aa774` versus `cf996cb`. Quote the numbers. 2. If the indexer is the cause: coalesce commits (debounce ~250–500 ms, commit at most once per window), and never block the write path on indexing. 3. If the notes lock is the cause: shrink the critical section (compute outside the lock, hold it only for the read-modify-write of the file). 4. Budget: 24 concurrent task creates for one user complete in < 3 s total on a loaded box, with p95 single create < 150 ms idle. Keep the adversarial SLOW threshold as the regression gate. Not a merge blocker (owner rule: performance issues are filed, not blocking), but fix it soon: it's on the capture path.

kayg commented

2026-09-24 20:11:08 +00:00

Author

Owner

Starting task-perf in branch job/task-perf at base 1c0af77932. I have read issue #71 and am establishing a release-mode task-create benchmark before making behavior changes.

Starting task-perf in branch job/task-perf at base 1c0af779321a7da31e1d5644b7f4d7a047863e99. I have read issue #71 and am establishing a release-mode task-create benchmark before making behavior changes.

kayg commented

2026-09-24 20:46:33 +00:00

Author

Owner

Five alternating release-mode pairs completed on CPUs 6,7. Each revision had 25 sequential Task creates and five 24-request storms (12 workers). The host was not idle: load average at the five pair starts was 26.09, 26.09, 26.01, 25.53, and 25.53 on 8 cores.

Measured distributions (p50; p95; min–max):

41aa774 single create: 31.7 ms; 217.0 ms; 13.3–433.9 ms. 24-create storm total: 1.049 s; 1.475 s; 0.467–1.475 s.
cf996cb single create: 35.9 ms; 236.0 ms; 13.3–490.4 ms. 24-create storm total: 0.819 s; 2.285 s; 0.502–2.285 s.

These loaded-host samples do not reproduce a large release-mode regression after the search merge; the cf996cb storm p95 is below 3 s, but the idle single-create budget cannot be evaluated from this host. I am tracing the lock and asynchronous indexer before selecting a fix.

Five alternating release-mode pairs completed on CPUs 6,7. Each revision had 25 sequential Task creates and five 24-request storms (12 workers). The host was not idle: load average at the five pair starts was 26.09, 26.09, 26.01, 25.53, and 25.53 on 8 cores. Measured distributions (p50; p95; min–max): - 41aa774 single create: 31.7 ms; 217.0 ms; 13.3–433.9 ms. 24-create storm total: 1.049 s; 1.475 s; 0.467–1.475 s. - cf996cb single create: 35.9 ms; 236.0 ms; 13.3–490.4 ms. 24-create storm total: 0.819 s; 2.285 s; 0.502–2.285 s. These loaded-host samples do not reproduce a large release-mode regression after the search merge; the `cf996cb` storm p95 is below 3 s, but the idle single-create budget cannot be evaluated from this host. I am tracing the lock and asynchronous indexer before selecting a fix.

kayg commented

2026-09-24 21:08:56 +00:00

Author

Owner

A second five-round diagnostic used one patched release server on CPUs 6,7 and alternated normal Task creates (attach to latest Log) with standalone creates. The host stayed loaded: five-minute load average was about 25 on 8 cores. Normal attached storm totals had p50 0.841 s, p95 5.103 s (0.453–5.103 s); standalone storm totals had p50 0.358 s, p95 2.774 s (0.104–2.774 s). Per-request storm latency was p50/p95 339/2,614 ms attached and 160/1,335 ms standalone. The fifth pair had the largest host-load spikes, so the p95 storm totals are noisy.

Both modes create the same Task files and Task Index rows; the normal path additionally mutates and re-indexes the shared Daily note. This points to serialized Daily note attachment work as the extra cost. The Task file's unique, durable create is now outside the per-user lock. The search actor already does its work in the background with a 120 ms debounce; these results do not isolate an indexer regression, so I left indexer commit behavior unchanged. Idle-host latency remains unmeasured.

A second five-round diagnostic used one patched release server on CPUs 6,7 and alternated normal Task creates (attach to latest Log) with standalone creates. The host stayed loaded: five-minute load average was about 25 on 8 cores. Normal attached storm totals had p50 0.841 s, p95 5.103 s (0.453–5.103 s); standalone storm totals had p50 0.358 s, p95 2.774 s (0.104–2.774 s). Per-request storm latency was p50/p95 339/2,614 ms attached and 160/1,335 ms standalone. The fifth pair had the largest host-load spikes, so the p95 storm totals are noisy. Both modes create the same Task files and Task Index rows; the normal path additionally mutates and re-indexes the shared Daily note. This points to serialized Daily note attachment work as the extra cost. The Task file's unique, durable create is now outside the per-user lock. The search actor already does its work in the background with a 120 ms debounce; these results do not isolate an indexer regression, so I left indexer commit behavior unchanged. Idle-host latency remains unmeasured.

kayg commented

2026-09-24 22:49:20 +00:00

Author

Owner

Task-perf complete.

Head: e9293254adf7fbacd0e1954ec942512beb087de9 (job/task-perf).

Finding and change:

The Task create handler was unchanged between 41aa774 and cf996cb. The search actor already batches updates asynchronously with a 120 ms debounce, so Task creation does not wait for Tantivy commits. The historical measurements do not isolate a regression from that merge.
The Notes per-user lock covered Task validation, construction, and a durable write to a new unique Task path. Those steps now happen before the lock. The lock still protects the Task Index projection and the shared Daily note selection/attachment path to preserve write ordering.
The standalone comparison showed less time in concurrent Task requests when Daily note attachment was skipped. I kept the real attachment path in the default benchmark.

Release measurements used five alternating rounds with taskset -c 6,7; each round recorded five sequential creates and one 24-request storm at concurrency 12. Host load was 24–26 during the historical comparison and rose to 26–31 during the lock comparison; this was not an idle-machine run.

Historical comparison:

41aa774: single create p50 31.7 ms, p95 217.0 ms, spread 13.3–433.9 ms; storm total p50 1.049 s, p95 1.475 s, spread 0.467–1.475 s.
cf996cb: single create p50 35.9 ms, p95 236.0 ms, spread 13.3–490.4 ms; storm total p50 0.819 s, p95 2.285 s, spread 0.502–2.285 s.

Lock comparison under higher and changing host load (cf996cb versus the current build): before the lock change, single p50/p95 was 74.3/807.4 ms (spread 27.7–866.9 ms) and storm total p50/p95 was 1.788/6.097 s (spread 0.543–6.097 s). After the lock change, single p50/p95 was 70.7/585.2 ms (spread 15.4–949.1 ms) and storm total p50/p95 was 2.158/5.622 s (spread 1.327–5.622 s). These noisy runs do not prove a causal improvement. The post-change storm median was below 3 s; its p95 was not. The idle single-create p95 target remains unmeasured.

Gates:

CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo fmt --check: exit 0, no output.
Clippy command: env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo clippy --workspace --all-targets -- -D warnings. Output:

   Compiling openssl-sys v0.9.117
   Compiling calternal-server v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-server)
   Compiling openssl v0.10.81
   Compiling webauthn-attestation-ca v0.5.5
   Compiling webauthn-rs-core v0.5.5
   Compiling webauthn-authenticator-rs v0.5.5
   Compiling ece v2.4.2
   Compiling tokio-native-tls v0.3.1
   Compiling hyper-tls v0.5.0
   Compiling web-push v0.11.0
   Compiling webauthn-rs v0.5.5
    Checking calternal-auth v0.1.0 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-auth)
    Checking calternal-plugin-files v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/files)
    Checking calternal-plugin-calendar v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/calendar)
    Checking calternal-collab v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-collab)
    Checking calternal-plugin-notifications v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/notifications)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 21s

env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo test --workspace: exit 0. Relevant output, verbatim:

test result: 453 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.45s
test result: 16 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.96s
test result: 10 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.19s
test result: 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.72s
test result: 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.54s

env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ bash tests/adversarial/run.sh: exit 0. Output ended with ==== FINDINGS 0 and ==== ROUND 2 FINDINGS 0. There was no Task storm … SLOW finding.

Decision not covered by DESIGN.md: keep the shared Daily note read/modify/write and related Notes Index work serialized, while moving only work on the fresh Task identity outside the lock. The host did not become idle, so I recorded the noisy results and left the idle latency target explicitly unverified.

Task-perf complete. Head: `e9293254adf7fbacd0e1954ec942512beb087de9` (`job/task-perf`). Finding and change: - The Task create handler was unchanged between `41aa774` and `cf996cb`. The search actor already batches updates asynchronously with a 120 ms debounce, so Task creation does not wait for Tantivy commits. The historical measurements do not isolate a regression from that merge. - The Notes per-user lock covered Task validation, construction, and a durable write to a new unique Task path. Those steps now happen before the lock. The lock still protects the Task Index projection and the shared Daily note selection/attachment path to preserve write ordering. - The standalone comparison showed less time in concurrent Task requests when Daily note attachment was skipped. I kept the real attachment path in the default benchmark. Release measurements used five alternating rounds with `taskset -c 6,7`; each round recorded five sequential creates and one 24-request storm at concurrency 12. Host load was 24–26 during the historical comparison and rose to 26–31 during the lock comparison; this was not an idle-machine run. Historical comparison: - `41aa774`: single create p50 31.7 ms, p95 217.0 ms, spread 13.3–433.9 ms; storm total p50 1.049 s, p95 1.475 s, spread 0.467–1.475 s. - `cf996cb`: single create p50 35.9 ms, p95 236.0 ms, spread 13.3–490.4 ms; storm total p50 0.819 s, p95 2.285 s, spread 0.502–2.285 s. Lock comparison under higher and changing host load (`cf996cb` versus the current build): before the lock change, single p50/p95 was 74.3/807.4 ms (spread 27.7–866.9 ms) and storm total p50/p95 was 1.788/6.097 s (spread 0.543–6.097 s). After the lock change, single p50/p95 was 70.7/585.2 ms (spread 15.4–949.1 ms) and storm total p50/p95 was 2.158/5.622 s (spread 1.327–5.622 s). These noisy runs do not prove a causal improvement. The post-change storm median was below 3 s; its p95 was not. The idle single-create p95 target remains unmeasured. Gates: - `CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo fmt --check`: exit 0, no output. - Clippy command: `env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo clippy --workspace --all-targets -- -D warnings`. Output: ```text Compiling openssl-sys v0.9.117 Compiling calternal-server v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-server) Compiling openssl v0.10.81 Compiling webauthn-attestation-ca v0.5.5 Compiling webauthn-rs-core v0.5.5 Compiling webauthn-authenticator-rs v0.5.5 Compiling ece v2.4.2 Compiling tokio-native-tls v0.3.1 Compiling hyper-tls v0.5.0 Compiling web-push v0.11.0 Compiling webauthn-rs v0.5.5 Checking calternal-auth v0.1.0 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-auth) Checking calternal-plugin-files v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/files) Checking calternal-plugin-calendar v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/calendar) Checking calternal-collab v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/calternal-collab) Checking calternal-plugin-notifications v0.0.1 (/home/kayg/Developer/calternal-wt/task-perf/crates/plugins/notifications) Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 21s ``` - `env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ CARGO_PROFILE_DEV_DEBUG=line-tables-only CARGO_INCREMENTAL=0 cargo test --workspace`: exit 0. Relevant output, verbatim: ```text test result: 453 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.45s test result: 16 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.96s test result: 10 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.19s test result: 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.72s test result: 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.54s ``` - `env -u RUSTC_WRAPPER CC=/usr/bin/cc CXX=/usr/bin/c++ bash tests/adversarial/run.sh`: exit 0. Output ended with `==== FINDINGS 0` and `==== ROUND 2 FINDINGS 0`. There was no `Task storm … SLOW` finding. Decision not covered by DESIGN.md: keep the shared Daily note read/modify/write and related Notes Index work serialized, while moving only work on the fresh Task identity outside the lock. The host did not become idle, so I recorded the noisy results and left the idle latency target explicitly unverified.

kayg referenced this issue

2026-09-24 23:08:28 +00:00

Adversarial harness: refresh passkey freshness before admin probes; update shared-listing probe for Index listings; load-aware SLOW #76

kayg referenced this issue from a commit

2026-09-24 23:13:21 +00:00

Merge job/task-perf: shorter task-create lock and a release benchmark (#71)

kayg commented

2026-10-01 05:13:00 +00:00

Author

Owner

Hygiene review: the storm and adversarial runs passed without SLOW findings, but the idle single-create latency target remains unmeasured. Keeping #71 open until that target is checked.

kayg commented

2026-10-03 11:58:59 +00:00

Author

Owner

The lock change is on origin/dev, but the job report says the idle single-create p95 target remains unmeasured. The storm evidence is load-sensitive, so leaving this performance issue open for a controlled measurement.

kayg referenced this issue

2026-10-03 12:04:41 +00:00

Issue hygiene sweep 2026-10-03 #1008

kayg referenced this issue

2026-10-03 12:05:35 +00:00

Moving in by dropping Markdown folders: find and fix what breaks (replaces the dedicated importer) #719

kayg referenced this issue

2026-10-03 12:56:40 +00:00

Issue hygiene sweep 2026-10-03 #1008

Rows
Columns

Perf: task create serializes at ~0.4 s under a 24-request storm after search indexer merge #71