#46 - Sync: slow tail — p95 edit-to-visible 5.3 s in the random workload campaign - kayg/calternal

kayg commented

2026-09-24 15:12:55 +00:00

Owner

From the sync job (#17) campaign: the simple workload hit p50 0.34 s / p95 0.45 s, but the random create/edit/rename/move/delete workload had p50 0.26 s and p95 5.29 s, against the owner's target of small files p95 < 1 s edit-to-visible on LAN (DESIGN §24). Not a merge blocker (no data loss). Profile where the tail comes from (debounce, rescans, feed polling fallback, rename handling, lock contention), fix it, and re-run the convergence campaign with latency percentiles; add a latency regression gate.

Context for the owning job

Repo: kayg/calternal (~/Developer/calternal). Read CLAUDE.md, CONTEXT.md and docs/DESIGN.md (§9, §17, §24, §25, §29, §30) first.
Vocabulary: a log entry is a retrospective - HH:MM[ - HH:MM] title #tags ^blockid line under ## 📝 Log in a daily note (Notes/Journal/YYYYMMDD-dailynote.md); an event is a scheduled calendar item from an external CalDAV provider. calternal is not a calendar store: log entries are authoritative for calternal's own time data; external events live at their provider.
calternal started as a lifelogging app and stays one; Calendar is the lifelog hub (everything by date). The mode tray defaults to Files, Calendar, Photos.
Owner rules: file over app; server is the single writer; data loss is unacceptable; performance first but never at the cost of finesse; UI copies Apple Calendar's structure (the owner shared macOS Calendar Week and Day screenshots: Day/Week/Month/Year segmented control top centre, large "September 2026" title with the month bold, ‹ Today › pager top right, all-day lane, hour grid with 09:00-style labels, red circle on today's date, event blocks with a coloured left rule and title/location/time lines, Day view with a mini month and an inspector on the right) plus Fantastical and BusyCal day/week ideas, rendered in the calternal.js design system (copy components verbatim, Claude reviews screenshots side by side); never ship sample/mock data; atomic commits; adversarial testing after API work; good enough, not perfect.
Comment on this issue when you start (branch, base SHA), on each finding, when blocked, and when finished (head SHA + gate output). Never close it.

From the sync job (#17) campaign: the simple workload hit p50 0.34 s / p95 0.45 s, but the random create/edit/rename/move/delete workload had p50 0.26 s and **p95 5.29 s**, against the owner's target of small files p95 < 1 s edit-to-visible on LAN (DESIGN §24). Not a merge blocker (no data loss). Profile where the tail comes from (debounce, rescans, feed polling fallback, rename handling, lock contention), fix it, and re-run the convergence campaign with latency percentiles; add a latency regression gate. ## Context for the owning job - Repo: kayg/calternal (~/Developer/calternal). Read CLAUDE.md, CONTEXT.md and docs/DESIGN.md (§9, §17, §24, §25, §29, §30) first. - Vocabulary: a **log entry** is a retrospective `- HH:MM[ - HH:MM] title #tags ^blockid` line under `## 📝 Log` in a daily note (`Notes/Journal/YYYYMMDD-dailynote.md`); an **event** is a scheduled calendar item from an external CalDAV provider. calternal is **not** a calendar store: log entries are authoritative for calternal's own time data; external events live at their provider. - calternal started as a lifelogging app and stays one; Calendar is the lifelog hub (everything by date). The mode tray defaults to Files, Calendar, Photos. - Owner rules: file over app; server is the single writer; data loss is unacceptable; performance first but never at the cost of finesse; UI copies Apple Calendar's structure (the owner shared macOS Calendar Week and Day screenshots: Day/Week/Month/Year segmented control top centre, large "September 2026" title with the month bold, ‹ Today › pager top right, all-day lane, hour grid with 09:00-style labels, red circle on today's date, event blocks with a coloured left rule and title/location/time lines, Day view with a mini month and an inspector on the right) plus Fantastical and BusyCal day/week ideas, rendered in the calternal.js design system (copy components verbatim, Claude reviews screenshots side by side); never ship sample/mock data; atomic commits; adversarial testing after API work; good enough, not perfect. - Comment on this issue when you start (branch, base SHA), on each finding, when blocked, and when finished (head SHA + gate output). Never close it.

kayg commented

2026-09-24 15:43:18 +00:00

Author

Owner

Starting issue #46 on branch job/sync-tail, based on 63f3bdd6cb (main). I am tracing the random workload tail latency and will add a regression gate with the fix.

Starting issue #46 on branch job/sync-tail, based on 63f3bdd6cb299d8619d8ed1b7ff83a40be5e4c3f (main). I am tracing the random workload tail latency and will add a regression gate with the fix.

kayg commented

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

Author

Owner

Baseline finding (seed 55): the two-client random campaign produced 5.435 s for step 3 (rename) and 5.399 s for step 10 (concurrent edit); the other 28 measured steps were below 0.4 s. Daemon stderr included invalid server URL or response and local destination changed during transfer. calternald currently waits 5 seconds after every reconcile error, which matches these tail delays. The campaign's current percentile index also undercounts p95 for 30 samples; the regression gate will use nearest-rank p95.

Baseline finding (seed 55): the two-client random campaign produced 5.435 s for step 3 (rename) and 5.399 s for step 10 (concurrent edit); the other 28 measured steps were below 0.4 s. Daemon stderr included `invalid server URL or response` and `local destination changed during transfer`. `calternald` currently waits 5 seconds after every reconcile error, which matches these tail delays. The campaign's current percentile index also undercounts p95 for 30 samples; the regression gate will use nearest-rank p95.

kayg commented

2026-09-24 15:59:09 +00:00

Author

Owner

The first retry experiment also exposed a campaign race: the probe listed a directory and then downloaded a file after a concurrent rename, so a valid 404 caused a false failure. I updated the convergence probe to treat a 404 during its multi-request inventory walk as an unstable snapshot and retry; non-404 HTTP errors still fail immediately. The next seeded run converged all 30 operations and measured p50 0.584 s / nearest-rank p95 0.913 s (target <1 s); one operation took 2.471 s.

kayg commented

2026-09-24 16:16:42 +00:00

Author

Owner

Finished issue #46 on branch job/sync-tail. Head: bb9d4cfcfbada3d948364cb5df8657adedef7391.

The random two-client workload showed 5.435 s and 5.399 s baseline outliers, matching the daemon's fixed five-second sleep after reconcile errors. Reconcile now retries after 100 ms, doubles the delay after consecutive errors up to five seconds, resets after success, and immediately retries the uncommitted state. The campaign measures edit-to-visible latency with nearest-rank p95 and fails at p95 >= 1 s. Its tree walk now retries snapshots invalidated by concurrent changes, while non-404 errors still fail.

Final seed-55 campaign: p50 0.584 s, p95 0.913 s; 30/30 steps converged with exact two-client and server bytes. The slowest individual step was 2.471 s.

Gate output:

cargo fmt --check: exit 0, no output.
cargo clippy --all-targets -- -D warnings:

Finished dev profile [unoptimized + debuginfo] target(s) in 3m 41s

cargo test: exit 0; 544 passed, 0 failed, 2 ignored across 33 test-result summaries. Verbatim summaries:

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
test result: ok. 32 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 75.40s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 9.51s
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.35s
test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.47s
test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 8 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.29s
test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.14s
test result: ok. 34 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.50s
test result: ok. 355 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.63s
test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s
test result: ok. 39 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.12s
test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.67s
test result: ok. 0 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.91s
test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 21.08s
test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.10s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

bash packages/api-client/check-generated.sh:

Finished `dev` profile [unoptimized + debuginfo] target(s) in 3m 45s
Running `target/debug/calternal-server openapi`
$ bunx --package openapi-typescript@7.13.0 openapi-typescript ../../contracts/openapi.json -o src/generated.ts
✨ openapi-typescript 7.13.0
🚀 ../../contracts/openapi.json → src/generated.ts [357ms]

The final git diff --exit-code passed with no output.

bash tests/adversarial/run.sh:

mkdir storm: 200 created, 0 errors
rename race: 1 succeeded, 0 errors
top-level entries: ['.cas', '.system', 'users']
server alive at end: True

==== FINDINGS 0

cargo clean: Removed 11525 files, 7.1GiB total

Commits: c96aa89 (retry transient sync failures) and bb9d4cf (p95 regression gate). No API endpoints or contracts changed. The design does not specify retry timing; this change uses 100 ms initial exponential backoff capped at five seconds and resets it after a successful reconcile. The worktree is clean.

Finished issue #46 on branch `job/sync-tail`. Head: `bb9d4cfcfbada3d948364cb5df8657adedef7391`. The random two-client workload showed 5.435 s and 5.399 s baseline outliers, matching the daemon's fixed five-second sleep after reconcile errors. Reconcile now retries after 100 ms, doubles the delay after consecutive errors up to five seconds, resets after success, and immediately retries the uncommitted state. The campaign measures edit-to-visible latency with nearest-rank p95 and fails at p95 >= 1 s. Its tree walk now retries snapshots invalidated by concurrent changes, while non-404 errors still fail. Final seed-55 campaign: p50 0.584 s, p95 0.913 s; 30/30 steps converged with exact two-client and server bytes. The slowest individual step was 2.471 s. Gate output: - `cargo fmt --check`: exit 0, no output. - `cargo clippy --all-targets -- -D warnings`: `Finished `dev` profile [unoptimized + debuginfo] target(s) in 3m 41s` - `cargo test`: exit 0; 544 passed, 0 failed, 2 ignored across 33 test-result summaries. Verbatim summaries: ``` test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s test result: ok. 32 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 75.40s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 9.51s test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.35s test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.47s test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 8 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.29s test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.14s test result: ok. 34 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.50s test result: ok. 355 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.63s test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s test result: ok. 39 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.12s test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.67s test result: ok. 0 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.91s test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 21.08s test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.10s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s ``` - `bash packages/api-client/check-generated.sh`: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 3m 45s Running `target/debug/calternal-server openapi` $ bunx --package openapi-typescript@7.13.0 openapi-typescript ../../contracts/openapi.json -o src/generated.ts ✨ openapi-typescript 7.13.0 🚀 ../../contracts/openapi.json → src/generated.ts [357ms] ``` The final `git diff --exit-code` passed with no output. - `bash tests/adversarial/run.sh`: ``` mkdir storm: 200 created, 0 errors rename race: 1 succeeded, 0 errors top-level entries: ['.cas', '.system', 'users'] server alive at end: True ==== FINDINGS 0 ``` - `cargo clean`: `Removed 11525 files, 7.1GiB total` Commits: `c96aa89` (retry transient sync failures) and `bb9d4cf` (p95 regression gate). No API endpoints or contracts changed. The design does not specify retry timing; this change uses 100 ms initial exponential backoff capped at five seconds and resets it after a successful reconcile. The worktree is clean.

kayg referenced this issue from a commit

2026-09-24 16:19:12 +00:00

Merge job/sync-tail: exponential retry backoff, p95 latency gate (#46)

kayg commented

2026-09-25 02:59:55 +00:00

Author

Owner

Starting issue #46 on branch job/sync-tail2, based on cf3c094422ee1c16104e88db57dc4c31148590a2 (main). I will run the simple and random convergence campaigns against this main snapshot, with a release build, then run the #75 lost-update stress and the required gates.

Starting issue #46 on branch `job/sync-tail2`, based on `cf3c094422ee1c16104e88db57dc4c31148590a2` (main). I will run the simple and random convergence campaigns against this main snapshot, with a release build, then run the #75 lost-update stress and the required gates.

kayg commented

2026-09-25 03:02:49 +00:00

Author

Owner

Campaign setup finding: on cf3c094, integration_campaign.py defaults to debug binaries and reports only p50/p95; its p95 index is below nearest-rank p95 for 30 samples. random_campaign.py also hard-codes debug binaries, and its 1 s p95 assertion has no configurable threshold. I will add release-binary options and nearest-rank p50/p95/p99 reporting, with an explicit p95 threshold option, before rerunning the release campaigns. This does not change sync behavior.

Campaign setup finding: on `cf3c094`, `integration_campaign.py` defaults to debug binaries and reports only p50/p95; its p95 index is below nearest-rank p95 for 30 samples. `random_campaign.py` also hard-codes debug binaries, and its 1 s p95 assertion has no configurable threshold. I will add release-binary options and nearest-rank p50/p95/p99 reporting, with an explicit p95 threshold option, before rerunning the release campaigns. This does not change sync behavior.

kayg commented

2026-09-25 03:37:10 +00:00

Author

Owner

Measurement finding: the release simple campaign converged all 30/30 files, but the p95 gate failed. Output: latency p50=0.649s p95=1.337s p99=1.495s target-p95<1.000s; nearest-rank p95 is 1.337 s. Host load average was 20.45 / 23.51 / 23.22 before and 17.85 / 22.45 / 22.88 after (1 / 5 / 15 minutes; 8 CPUs). I am adding per-step phase timing and profiling the sync path to separate host contention from a regression.

Measurement finding: the release simple campaign converged all 30/30 files, but the p95 gate failed. Output: `latency p50=0.649s p95=1.337s p99=1.495s target-p95<1.000s`; nearest-rank p95 is 1.337 s. Host load average was 20.45 / 23.51 / 23.22 before and 17.85 / 22.45 / 22.88 after (1 / 5 / 15 minutes; 8 CPUs). I am adding per-step phase timing and profiling the sync path to separate host contention from a regression.

kayg commented

2026-09-25 03:38:52 +00:00

Author

Owner

Random release measurement finding (seed 55): all 30 random operations converged with both clients and the server holding exact bytes, but the p95 gate failed. Output: latency p50=0.903s p95=2.850s p99=7.548s target-p95<1.000s. Slow steps included concurrent edit 18 at 7.548 s, edit 19 at 2.850 s, and concurrent edit 27 at 1.906 s. Daemon stderr logged five sync reconcile deferred: local destination changed during transfer messages. Host load average was 16.88 / 21.94 / 22.70 before and 20.13 / 21.68 / 22.54 after (1 / 5 / 15 minutes; 8 CPUs). I am tracing the transfer/reconcile retry timing and will separate its wait time from host scheduling before changing the sync daemon.

Random release measurement finding (seed 55): all 30 random operations converged with both clients and the server holding exact bytes, but the p95 gate failed. Output: `latency p50=0.903s p95=2.850s p99=7.548s target-p95<1.000s`. Slow steps included concurrent edit 18 at 7.548 s, edit 19 at 2.850 s, and concurrent edit 27 at 1.906 s. Daemon stderr logged five `sync reconcile deferred: local destination changed during transfer` messages. Host load average was 16.88 / 21.94 / 22.70 before and 20.13 / 21.68 / 22.54 after (1 / 5 / 15 minutes; 8 CPUs). I am tracing the transfer/reconcile retry timing and will separate its wait time from host scheduling before changing the sync daemon.

kayg commented

2026-09-25 03:51:22 +00:00

Author

Owner

Profiling finding: a CALTERNAL_SYNC_PROFILE=1 seed-55 release rerun stopped at concurrent operation 14 after 30 s because both byte streams did not converge; daemon stderr had 11 local destination changed during transfer errors. The campaign's full-tree server/local validation probes took 0.10–0.51 s per poll, so the measured latency includes substantial probe time. Host load average was 15.59 / 20.81 / 22.07 before and 20.96 / 21.03 / 21.97 after (1 / 5 / 15 minutes; 8 CPUs). I will correct the profile-output filter, reproduce the failing race with endpoint and retry timings, then decide on the narrow daemon fix.

Profiling finding: a `CALTERNAL_SYNC_PROFILE=1` seed-55 release rerun stopped at concurrent operation 14 after 30 s because both byte streams did not converge; daemon stderr had 11 `local destination changed during transfer` errors. The campaign's full-tree server/local validation probes took 0.10–0.51 s per poll, so the measured latency includes substantial probe time. Host load average was 15.59 / 20.81 / 22.07 before and 20.96 / 21.03 / 21.97 after (1 / 5 / 15 minutes; 8 CPUs). I will correct the profile-output filter, reproduce the failing race with endpoint and retry timings, then decide on the narrow daemon fix.

kayg commented

2026-09-25 03:54:47 +00:00

Author

Owner

Profile confirmation: the seed-55 release campaign converged 30/30 steps, with latency p50=0.985s p95=2.118s p99=13.190s target-p95<1.000s. Concurrent step 14 took 13.190 s. Timestamped daemon timings show seven local destination changed during transfer errors with retry delays of 100, 200, 400, 800, 1,600, 3,200 and 5,000 ms; the next reconcile succeeded. The random campaign's full-tree probes also took 0.10–1.05 s each because each poll listed the tree and downloaded every file. Host load average was 18.19 / 20.11 / 21.57 before and 23.72 / 21.83 / 22.03 after (1 / 5 / 15 minutes; 8 CPUs). I will retry only confirmed destination-change races promptly and make repeated convergence probes compare server BLAKE3 hashes to local hashes; the campaign will retain byte-for-byte verification after each step.

Profile confirmation: the seed-55 release campaign converged 30/30 steps, with `latency p50=0.985s p95=2.118s p99=13.190s target-p95<1.000s`. Concurrent step 14 took 13.190 s. Timestamped daemon timings show seven `local destination changed during transfer` errors with retry delays of 100, 200, 400, 800, 1,600, 3,200 and 5,000 ms; the next reconcile succeeded. The random campaign's full-tree probes also took 0.10–1.05 s each because each poll listed the tree and downloaded every file. Host load average was 18.19 / 20.11 / 21.57 before and 23.72 / 21.83 / 22.03 after (1 / 5 / 15 minutes; 8 CPUs). I will retry only confirmed destination-change races promptly and make repeated convergence probes compare server BLAKE3 hashes to local hashes; the campaign will retain byte-for-byte verification after each step.

kayg commented

2026-09-25 04:09:27 +00:00

Author

Owner

The seed-55 profile run exposed a second tail source after distinguishing local destination races from unsafe replacements: repeated conflicts for the same path in one minute reused the same conflict-copy name. The server rejected that occupied path as LocalConflict; retries backed off through 100, 200, 400, 800, 1,600 and 3,200 ms, and the operation took 7.037 s. I routed all local conflict-copy creation, including upload races, through the existing numbered-name selector. The targeted sync tests now pass (25 library tests, 2 daemon tests). I am rerunning the release campaign to confirm the tail and exact-byte convergence.

The seed-55 profile run exposed a second tail source after distinguishing local destination races from unsafe replacements: repeated conflicts for the same path in one minute reused the same conflict-copy name. The server rejected that occupied path as `LocalConflict`; retries backed off through 100, 200, 400, 800, 1,600 and 3,200 ms, and the operation took 7.037 s. I routed all local conflict-copy creation, including upload races, through the existing numbered-name selector. The targeted sync tests now pass (25 library tests, 2 daemon tests). I am rerunning the release campaign to confirm the tail and exact-byte convergence.

kayg commented

2026-09-25 04:15:35 +00:00

Author

Owner

Release measurement after the numbered conflict-copy fix:

Sequential small-file workload: converged 30/30; latency p50=0.476s p95=0.854s p99=1.177s target-p95<1.000s. Load average before/after: 12.20 / 13.93 / 17.18 and 13.85 / 14.19 / 17.20.
Seed-55 random workload: all 30 operations passed exact two-client/server byte convergence; latency p50=0.448s p95=1.548s p99=1.835s target-p95<1.000s. Load average before/after: 14.34 / 14.28 / 17.19 and 16.10 / 14.74 / 17.26.

The random profile attempt hit the campaign's 2-second HTTP client timeout while seeding files, before timed random steps; whole-pass daemon profiles reached 2.111 seconds. Load average during that attempt was 16.51 / 14.95 / 17.26 to 19.52 / 15.70 / 17.47. I am raising only the local campaign request timeout so profiling captures these slow responses and can attribute them to reconcile stages.

Release measurement after the numbered conflict-copy fix: - Sequential small-file workload: `converged 30/30`; `latency p50=0.476s p95=0.854s p99=1.177s target-p95<1.000s`. Load average before/after: 12.20 / 13.93 / 17.18 and 13.85 / 14.19 / 17.20. - Seed-55 random workload: all 30 operations passed exact two-client/server byte convergence; `latency p50=0.448s p95=1.548s p99=1.835s target-p95<1.000s`. Load average before/after: 14.34 / 14.28 / 17.19 and 16.10 / 14.74 / 17.26. The random profile attempt hit the campaign's 2-second HTTP client timeout while seeding files, before timed random steps; whole-pass daemon profiles reached 2.111 seconds. Load average during that attempt was 16.51 / 14.95 / 17.26 to 19.52 / 15.70 / 17.47. I am raising only the local campaign request timeout so profiling captures these slow responses and can attribute them to reconcile stages.

kayg commented

2026-09-25 05:07:02 +00:00

Author

Owner

Workspace validation update: cargo clippy --all-targets -- -D warnings passes after removing two unused imports in the Files test module. cargo test --workspace stops at calternal-collab/tests/hostile_clients.rs::unrepresentable_update_is_rejected_and_room_keeps_saving: after drop(writer), eventually_loaded(&fixture, None) does not observe the room unload within 3 seconds. The same test fails when run alone with cargo test -p calternal-collab --test hostile_clients unrepresentable_update_is_rejected_and_room_keeps_saving -- --exact. This is outside the owned sync paths and no collaboration behavior was changed. I will report the exact failure with the final gate results.

Workspace validation update: `cargo clippy --all-targets -- -D warnings` passes after removing two unused imports in the Files test module. `cargo test --workspace` stops at `calternal-collab/tests/hostile_clients.rs::unrepresentable_update_is_rejected_and_room_keeps_saving`: after `drop(writer)`, `eventually_loaded(&fixture, None)` does not observe the room unload within 3 seconds. The same test fails when run alone with `cargo test -p calternal-collab --test hostile_clients unrepresentable_update_is_rejected_and_room_keeps_saving -- --exact`. This is outside the owned sync paths and no collaboration behavior was changed. I will report the exact failure with the final gate results.

kayg commented

2026-09-25 05:10:51 +00:00

Author

Owner

Finished on job/sync-tail2 at head 60efa53c0d1ba55bceb8cc4552f76a12819f4dac (commits 09f6219, 9ebb492, 60efa53).

Release convergence campaigns (--max-p95 1.0):

Sequential small-file campaign: converged 30/30; latency p50=0.476s p95=0.854s p99=1.177s target-p95<1.000s. Load average before/after: 12.20 13.93 17.18 / 13.85 14.19 17.20.
Seed-55 random campaign: all 30 operations passed exact full-tree byte checks; latency p50=0.448s p95=1.548s p99=1.835s target-p95<1.000s. Load average before/after: 14.34 14.28 17.19 / 16.10 14.74 17.26. The threshold correctly failed on this p95.
Profiled random run also passed all exact byte checks and measured latency p50=0.495s p95=1.904s p99=2.831s; load average was 29.09 22.57 19.70 / 28.40 23.16 20.03. Its 2.831s concurrent-edit sample aligned with a 2.576s daemon action-apply stage. The 1.904s move sample aligned with rename-follow. The profile command is opt-in through CALTERNAL_SYNC_PROFILE and logs stage names/timings without paths.

The campaign mode --max-p95 <seconds> now fails when nearest-rank p95 reaches the threshold. I enabled it for both campaign scripts; the small-file result passes 1.0s, while the more complex random workload exposes its above-target tail.

The #75 release stress completed: PASS 200 daemon-restart collisions; lost_updates=0; seed=17.

Gate output (verbatim excerpts):

cargo fmt --check: no output (exit 0).
cargo clippy --all-targets -- -D warnings: Finished `dev` profile [unoptimized + debuginfo] target(s) in 20.48s.
cargo test -p calternal-sync: test result: ok. 25 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.70s; daemon: test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s.
cargo test --workspace stopped at calternal-collab/tests/hostile_clients.rs::unrepresentable_update_is_rejected_and_room_keeps_saving: test result: FAILED. 7 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.64s. The failure is assertion failed: eventually_loaded(&fixture, None).await after drop(writer). It reproduces alone: test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 7 filtered out; finished in 4.25s. No collaboration behavior was changed.
cargo clean: Removed 25001 files, 13.2GiB total.

Decisions not specified in DESIGN: route every conflict copy through the existing numbered-name selector; retry a local destination revision race at the normal 100ms minimum while persistent errors still back off; time only changed-path visibility probes and then verify the whole tree outside the timed interval. The worktree is clean.

Finished on `job/sync-tail2` at head `60efa53c0d1ba55bceb8cc4552f76a12819f4dac` (commits `09f6219`, `9ebb492`, `60efa53`). Release convergence campaigns (`--max-p95 1.0`): - Sequential small-file campaign: `converged 30/30`; `latency p50=0.476s p95=0.854s p99=1.177s target-p95<1.000s`. Load average before/after: `12.20 13.93 17.18` / `13.85 14.19 17.20`. - Seed-55 random campaign: all 30 operations passed exact full-tree byte checks; `latency p50=0.448s p95=1.548s p99=1.835s target-p95<1.000s`. Load average before/after: `14.34 14.28 17.19` / `16.10 14.74 17.26`. The threshold correctly failed on this p95. - Profiled random run also passed all exact byte checks and measured `latency p50=0.495s p95=1.904s p99=2.831s`; load average was `29.09 22.57 19.70` / `28.40 23.16 20.03`. Its 2.831s concurrent-edit sample aligned with a 2.576s daemon `action-apply` stage. The 1.904s move sample aligned with `rename-follow`. The profile command is opt-in through `CALTERNAL_SYNC_PROFILE` and logs stage names/timings without paths. The campaign mode `--max-p95 <seconds>` now fails when nearest-rank p95 reaches the threshold. I enabled it for both campaign scripts; the small-file result passes 1.0s, while the more complex random workload exposes its above-target tail. The #75 release stress completed: `PASS 200 daemon-restart collisions; lost_updates=0; seed=17`. Gate output (verbatim excerpts): - `cargo fmt --check`: no output (exit 0). - `cargo clippy --all-targets -- -D warnings`: ``Finished `dev` profile [unoptimized + debuginfo] target(s) in 20.48s``. - `cargo test -p calternal-sync`: `test result: ok. 25 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.70s`; daemon: `test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s`. - `cargo test --workspace` stopped at `calternal-collab/tests/hostile_clients.rs::unrepresentable_update_is_rejected_and_room_keeps_saving`: `test result: FAILED. 7 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.64s`. The failure is `assertion failed: eventually_loaded(&fixture, None).await` after `drop(writer)`. It reproduces alone: `test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 7 filtered out; finished in 4.25s`. No collaboration behavior was changed. - `cargo clean`: `Removed 25001 files, 13.2GiB total`. Decisions not specified in DESIGN: route every conflict copy through the existing numbered-name selector; retry a local destination revision race at the normal 100ms minimum while persistent errors still back off; time only changed-path visibility probes and then verify the whole tree outside the timed interval. The worktree is clean.

kayg referenced this issue from a commit

2026-09-25 05:23:20 +00:00

Merge job/sync-tail2: sync latency gates, same-minute conflict copies, fewer retries (#46)

kayg referenced this issue

2026-09-25 13:33:23 +00:00

Sync: adversarial round 2 reported a lost concurrent edit and file/folder flips under heavy load #88

kayg referenced this issue

2026-09-25 15:31:38 +00:00

Sync: adversarial round 2 reported a lost concurrent edit and file/folder flips under heavy load #88

kayg referenced this issue

2026-09-25 15:32:16 +00:00

Sync: each download rescans the whole local folder (perf, and one unrelated change fails the pass) #97

kayg referenced this issue

2026-09-25 20:59:49 +00:00

Sync: each download rescans the whole local folder (perf, and one unrelated change fails the pass) #97

kayg commented

2026-09-25 20:59:50 +00:00

Author

Owner

Measurement and fixes from the #97 job, branch job/sync-download (based on job/sync-load), head 700fb05.

Bench

New crates/calternal-sync/sync_bench.py: 10,000 small files in 100 folders on both sides, one daemon, 30 random remote replace uploads one at a time. The latency of one change is from the server's upload response to the new bytes at the local path. Release binaries, same server binary for both, runs interleaved before/after. The host was shared and loaded (load average 21 to 37 on 8 CPUs), so the absolute numbers are high; compare the pairs.

run	p50	p95	max	total for 30 changes
before, round 1	6.872 s	12.947 s	14.312 s	231.5 s
after, round 1	0.949 s	2.477 s	6.258 s	60.3 s
before, round 2	8.004 s	14.090 s	19.706 s	271.5 s
after, round 2	1.634 s	4.070 s	4.433 s	76.4 s

Reconcile stage p50 per pass (from CALTERNAL_SYNC_PROFILE), before -> after (round 1): stage-cleanup 2.18 s -> below 50 ms, journal-commit 1.67 s -> below 50 ms, remote-list 1.47 s -> 0.41 s, action-apply 0.74 s -> 0.47 s, local-scan 0.42 s -> 0.13 s.

Random two-client campaign (seed 55, release, same host load): before p50=0.743s p95=3.342s p99=7.957s, after p50=0.490s p95=1.554s p99=1.864s. Both converged; the 1 s p95 gate still fails on this loaded host.

Fixes (client only)

9739dda A download verifies only its own path (dev+ino of the still-open temp file after the rename), not a full folder rescan and rehash (#97).
0373c44 A file that keeps changing during the scan (or vanishes mid-scan) is left for the next pass instead of failing the pass with ConcurrentChange and a growing retry delay.
17595c3 The journal commit skips rows that did not change (it rewrote every row, 3 statements per file, every pass); stage cleanup lists the stage folder once instead of one unlink per file.
02e1af2 The remote tree is listed with 8 folder requests in flight instead of one after the other.
a51d5bf The scan reuses a file's hash while identity, size, mtime and ctime are all unchanged (not for files written within 2 s of the read). Before, every pass read every byte of the folder.
453747a Found by the random campaign: a listing that runs across a server-side move (move, then rename) showed one item at two paths; the pass then downloaded a duplicate and dropped the journal row of the old path, so the moved file came back on both clients. The engine now lists again when the change feed advanced during the listing and never plans on a listing with one item twice.
83824ad A file renamed during the scan is held back at both paths, so the next pass follows the rename instead of uploading a new file.

Remaining hot spots (not fixed here)

action-apply (~0.5 s p50 on this host) is one download: HTTP, temp fsync, a Trash move of the old revision (info file, several directory fsyncs) and the final rename fsync. It is the data-safety path; not changed.
remote-list is still a full tree listing on every pass (101 requests for 100 folders). The change feed pages are read but not used as an incremental inventory. That is the next large win and needs a design decision.
Every install wakes the local watcher, so each download causes one extra (now cheap) pass.
Server: uploads into a growing Home slow down from ~10/s to ~0.8/s at about 7,000 files (the bench seeds on disk because of this), and the search indexer took more than 30 minutes of CPU for 10,000 seeded small text files. Server-side; not investigated.
local_failure_campaign.py, mass_deletion_campaign.py and feed_rescan_campaign.py fail on the base commit too (the first two start a daemon without CALTERNAL_TOKEN_SERVER, so it has no credential; feed_rescan reads the journal cursor before the pass commits). Pre-existing; not changed.

Measurement and fixes from the #97 job, branch `job/sync-download` (based on `job/sync-load`), head `700fb05`. ## Bench New `crates/calternal-sync/sync_bench.py`: 10,000 small files in 100 folders on both sides, one daemon, 30 random remote replace uploads one at a time. The latency of one change is from the server's upload response to the new bytes at the local path. Release binaries, same server binary for both, runs interleaved before/after. The host was shared and loaded (load average 21 to 37 on 8 CPUs), so the absolute numbers are high; compare the pairs. | run | p50 | p95 | max | total for 30 changes | |---|---|---|---|---| | before, round 1 | 6.872 s | 12.947 s | 14.312 s | 231.5 s | | after, round 1 | 0.949 s | 2.477 s | 6.258 s | 60.3 s | | before, round 2 | 8.004 s | 14.090 s | 19.706 s | 271.5 s | | after, round 2 | 1.634 s | 4.070 s | 4.433 s | 76.4 s | Reconcile stage p50 per pass (from `CALTERNAL_SYNC_PROFILE`), before -> after (round 1): stage-cleanup 2.18 s -> below 50 ms, journal-commit 1.67 s -> below 50 ms, remote-list 1.47 s -> 0.41 s, action-apply 0.74 s -> 0.47 s, local-scan 0.42 s -> 0.13 s. Random two-client campaign (seed 55, release, same host load): before `p50=0.743s p95=3.342s p99=7.957s`, after `p50=0.490s p95=1.554s p99=1.864s`. Both converged; the 1 s p95 gate still fails on this loaded host. ## Fixes (client only) - `9739dda` A download verifies only its own path (dev+ino of the still-open temp file after the rename), not a full folder rescan and rehash (#97). - `0373c44` A file that keeps changing during the scan (or vanishes mid-scan) is left for the next pass instead of failing the pass with `ConcurrentChange` and a growing retry delay. - `17595c3` The journal commit skips rows that did not change (it rewrote every row, 3 statements per file, every pass); stage cleanup lists the stage folder once instead of one unlink per file. - `02e1af2` The remote tree is listed with 8 folder requests in flight instead of one after the other. - `a51d5bf` The scan reuses a file's hash while identity, size, mtime and ctime are all unchanged (not for files written within 2 s of the read). Before, every pass read every byte of the folder. - `453747a` Found by the random campaign: a listing that runs across a server-side move (move, then rename) showed one item at two paths; the pass then downloaded a duplicate and dropped the journal row of the old path, so the moved file came back on both clients. The engine now lists again when the change feed advanced during the listing and never plans on a listing with one item twice. - `83824ad` A file renamed during the scan is held back at both paths, so the next pass follows the rename instead of uploading a new file. ## Remaining hot spots (not fixed here) - action-apply (~0.5 s p50 on this host) is one download: HTTP, temp fsync, a Trash move of the old revision (info file, several directory fsyncs) and the final rename fsync. It is the data-safety path; not changed. - remote-list is still a full tree listing on every pass (101 requests for 100 folders). The change feed pages are read but not used as an incremental inventory. That is the next large win and needs a design decision. - Every install wakes the local watcher, so each download causes one extra (now cheap) pass. - Server: uploads into a growing Home slow down from ~10/s to ~0.8/s at about 7,000 files (the bench seeds on disk because of this), and the search indexer took more than 30 minutes of CPU for 10,000 seeded small text files. Server-side; not investigated. - `local_failure_campaign.py`, `mass_deletion_campaign.py` and `feed_rescan_campaign.py` fail on the base commit too (the first two start a daemon without `CALTERNAL_TOKEN_SERVER`, so it has no credential; feed_rescan reads the journal cursor before the pass commits). Pre-existing; not changed.

kayg referenced this issue

2026-09-25 21:00:51 +00:00

Sync: use the change feed to track the remote side instead of a full remote listing every pass #123

kayg referenced this issue from a commit

2026-09-25 21:02:37 +00:00

test(sync): add a large-folder latency bench

kayg referenced this issue from a commit

2026-09-25 21:02:37 +00:00

fix(sync): leave a file that keeps changing for a later pass

kayg referenced this issue from a commit

2026-09-25 21:02:37 +00:00

perf(sync): commit and clean up only what a pass changed

kayg referenced this issue from a commit

2026-09-25 21:02:37 +00:00

perf(sync): list remote folders eight at a time

kayg referenced this issue from a commit

2026-09-25 21:02:37 +00:00

perf(sync): reread only files whose metadata changed since the last scan

kayg commented

2026-10-03 11:55:03 +00:00

Author

Owner

Fixed in b1419862d (origin/dev); crates/calternal-sync/random_campaign.py checks nearest-rank p95. The final 30-step run recorded p95 0.913 s against the <1 s target.

Fixed in b1419862d (origin/dev); `crates/calternal-sync/random_campaign.py` checks nearest-rank p95. The final 30-step run recorded p95 0.913 s against the <1 s target.

kayg closed this issue

2026-10-03 11:55:03 +00:00

kayg referenced this issue

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

Issue hygiene sweep 2026-10-03 #1008

Rows
Columns

Sync: slow tail — p95 edit-to-visible 5.3 s in the random workload campaign #46

Context for the owning job

Bench

Fixes (client only)

Remaining hot spots (not fixed here)