Keep the snapshot compaction replaces, and seed its test in one transaction #163

Merged
nectenda-agent merged 5 commits from worktree-nec-15-stall into main 2026-09-24 23:51:57 +01:00
Collaborator

Task: NEC-15 — https://projectron.nerchure.com/tasks/15

Re-lands the checkpoint writer from PR #145, which b6b264d took out after main's run 676 timed out in checkpoints.test.ts › past the compaction threshold, through the WebSocket path. The first commit restores it unchanged, with conformance.md regenerated. The rest explain the stall and fix it.

It was the test, not the writer. The test seeded its document with 510 appends, each committed alone at synchronous = FULL on the main thread. That is 510 fsyncs with the event loop blocked:

unfixed, loaded (run 757) fixed, loaded (run 760)
passed 0 / 30 30 / 30
seed p50 / max 5,747 / 9,042 ms 46 / 175 ms
error Test timed out in 5000ms at :271:3, main's exact one none
  • In the unfixed runs, every failure stopped before the client connected, so the threaded writer was never reached.
  • Idle, the unfixed seed took 1.6 s and always passed (run 756).
  • A Mac never reproduced it: its fsync does not reach stable storage, so the same seed costs about 40 ms there.
  • Both loaded runs had comparable disk load. The fsync probe put 510 appends at 6.2 s and 6.0 s.

The fix seeds in one transaction, so one fsync. The seed is setup, not the path under test.

Left for reference: checkpoint-soak.yml and packages/server/scripts/checkpoint-soak.mjs, dispatch-only like e2e-soak.yml. They loop the test on the runner, idle and beside N neighbours, and print a per-phase timeline and an fsync probe. The test prints its timeline only under the soak (CHECKPOINT_TIMELINE=1).

Seen, not chased: with the seed fixed, connect → first compaction rose to about 220 ms idle and 0.7–1.7 s loaded. The likely cause is the writer thread's cold start, now that the first job arrives about 25 ms after the server starts rather than seconds later. That is unverified. It happens once per server start, and even the worst case stays well inside the 5 s budget.

Changelog

The server now keeps earlier versions of each note when it compacts its history, instead of discarding them.

🤖 Generated with Claude Code

https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH

Task: NEC-15 — https://projectron.nerchure.com/tasks/15 Re-lands the checkpoint writer from PR #145, which b6b264d took out after `main`'s run 676 timed out in `checkpoints.test.ts › past the compaction threshold, through the WebSocket path`. The first commit restores it unchanged, with `conformance.md` regenerated. The rest explain the stall and fix it. **It was the test, not the writer.** The test seeded its document with 510 appends, each committed alone at `synchronous = FULL` on the main thread. That is 510 fsyncs with the event loop blocked: | | unfixed, loaded (run 757) | fixed, loaded (run 760) | |---|---|---| | passed | 0 / 30 | 30 / 30 | | seed p50 / max | 5,747 / 9,042 ms | 46 / 175 ms | | error | `Test timed out in 5000ms` at `:271:3`, main's exact one | none | - In the unfixed runs, every failure stopped before the client connected, so the threaded writer was never reached. - Idle, the unfixed seed took 1.6 s and always passed (run 756). - A Mac never reproduced it: its fsync does not reach stable storage, so the same seed costs about 40 ms there. - Both loaded runs had comparable disk load. The fsync probe put 510 appends at 6.2 s and 6.0 s. **The fix** seeds in one transaction, so one fsync. The seed is setup, not the path under test. **Left for reference:** `checkpoint-soak.yml` and `packages/server/scripts/checkpoint-soak.mjs`, dispatch-only like `e2e-soak.yml`. They loop the test on the runner, idle and beside N neighbours, and print a per-phase timeline and an fsync probe. The test prints its timeline only under the soak (`CHECKPOINT_TIMELINE=1`). **Seen, not chased:** with the seed fixed, connect → first compaction rose to about 220 ms idle and 0.7–1.7 s loaded. The likely cause is the writer thread's cold start, now that the first job arrives about 25 ms after the server starts rather than seconds later. That is unverified. It happens once per server start, and even the worst case stays well inside the 5 s budget. ## Changelog The server now keeps earlier versions of each note when it compacts its history, instead of discarding them. 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
Reverts b6b264d, which took out 206d1f6 and b7e3271 when the WebSocket
checkpoint test timed out at 5 s on main's run 676. This puts the change
back exactly as it was, with conformance.md regenerated against today's
spec, so the next commits can instrument the stall rather than guess at it.

Task: NEC-15

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
The WebSocket checkpoint test stalled for 5 s on main's run 676 and never on
a Mac. The test now writes a phase timeline to fd 2 (started, seeded,
connected, subscribed, compacted, edit logged, compacted again), with the seed
loop's total and slowest append, so a stall names the phase that ate it.

checkpoint-soak.yml loops the test on the runner, idle and then beside a
neighbour (the server suite on a loop and a one-fsync-at-a-time writer). It
first probes the disk with the same 510 FULL appends the test seeds with,
because a Mac's fsync never reaches the platter and cannot say what the
runner's costs.

Task: NEC-15

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
The first soak on the runner (run 756) called all 60 iterations failures:
it matched vitest's summary line, which is coloured on the runner. A pass is
now exit 0 and reaching the last phase. Its timings stand: the 510-append
seed took 1.6 s idle and 4.0 s (max 4.4 s) beside one neighbour, and
everything after the client connected took under 150 ms.

No iteration timed out, though, and run 676 failed beside two e2e suites
and another unit suite. load_factor runs that many neighbours at once, so
the unfixed test can be pushed to the failure it had on main before a fix
is judged against it.

The loop-lag figure is gone from the timeline: metrics.ts samples the same
window, so it reported 13 ms across a 4 s block.

Package scripts get the no-console exemption root scripts already have.

Task: NEC-15

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
Its 510 setup appends each committed alone at synchronous = FULL on the main
thread: 510 fsyncs with the event loop blocked. On a Mac that is about 40 ms,
because its fsync never reaches the platter. On the CI runner it was 1.6 s
idle, and beside three neighbours (checkpoint-soak run 757) 5.0-9.0 s, so the
unfixed test timed out 30 times in 30 with main's exact error, every time
before its client had connected. The threaded writer was never reached.

One transaction is one fsync. The seed is setup rather than the path under
test, which is the pushes and snapshots that follow through the writer.

Task: NEC-15

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
Print the checkpoint test's timeline only when the soak asks for it
All checks were successful
Release note / release-note (pull_request) Successful in 13s
CI / build (pull_request) Successful in 4m38s
CI / e2e (pull_request) Successful in 4m48s
CI / promote (pull_request) Has been skipped
Deploy site / deploy (push) Successful in 48s
CI / e2e (push) Successful in 4m50s
CI / build (push) Successful in 4m54s
CI / promote (push) Successful in 30s
43426ec50b
Seven lines on stderr in every CI run is noise once the question is
answered. checkpoint-soak.mjs sets CHECKPOINT_TIMELINE=1; nothing else does.

The fixed test on the runner, beside the same three neighbours that failed
the unfixed one 30 times in 30 (run 757), passed 30 in 30 (run 760), with
the seed at 46 ms p50 and 175 ms max instead of 5.7 s and 9.0 s.

Task: NEC-15

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0187PLDdwErbQsm6aZi7KXuH
Sign in to join this conversation.
No reviewers
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
Nectenda/nectenda!163
No description provided.