diff --git a/coordinator/cmd/drsyncd/main.go b/coordinator/cmd/drsyncd/main.go index cacf1f7..67b4cfc 100644 --- a/coordinator/cmd/drsyncd/main.go +++ b/coordinator/cmd/drsyncd/main.go @@ -250,9 +250,10 @@ func run(agentAddr, httpAddr, dataDir, apiTokenFile, tlsCert, tlsKey, tlsCA, smt // s.mu (and therefore every agent's grant/renew/complete call) for // however long that copy takes. // - // 20s ticks, TRUNCATE only every walCheckpointTruncateEvery of them (see - // RunWALCheckpoint/WALCheckpoint in store.go for the full history): the - // original 5-minute, TRUNCATE-only interval measured a live 10-agent + // PASSIVE every 60s, TRUNCATE every 200s — independent cadences (see + // RunWALCheckpoint in store.go for why they're no longer one ticker with + // TRUNCATE riding every Nth PASSIVE tick, and the full history below). + // The original 5-minute, TRUNCATE-only interval measured a live 10-agent // median WALCheckpoint hold of 33s (max 144s) — TRUNCATE needs an // exclusive lock over the whole WAL to shrink the file, held under s.mu // for the full copy-back duration, so every other coordinator write @@ -266,12 +267,22 @@ func run(agentAddr, httpAddr, dataDir, apiTokenFile, tlsCert, tlsKey, tlsCA, smt // content, no exclusive lock needed) with TRUNCATE only periodically // (reclaims file size, but by then PASSIVE has already drained most of // what it would otherwise have to copy) addresses that floor instead of - // just calling TRUNCATE more often. Moving checkpointing off s.mu - // entirely was considered and rejected: TRUNCATE's exclusive WAL lock is - // a SQLite-level constraint, not an app-level overcaution, so that would - // only trade a blocked goroutine for a SQLITE_BUSY retry loop of similar - // wall-clock cost. Re-measure after changing either number here. - go st.RunWALCheckpoint(ctx, 20*time.Second) + // just calling TRUNCATE more often — this got TRUNCATE's own median down + // to 2.95s (max 8.7s). But a 6-hour, 10-agent test at PASSIVE=20s (one + // ticker, TRUNCATE riding every 10th tick) found PASSIVE's own median + // hold (3.4s) running *higher* than TRUNCATE's — at 20s there is so + // little real WAL content per call that PASSIVE's hold is dominated by + // the same fixed per-call overhead that limited TRUNCATE before the + // split, just paid 9x as often. Decoupling the two cadences (this call) + // lets PASSIVE widen to accumulate more real backlog per call — 60s, + // still far more frequent than the original 5-minute baseline — without + // having to also widen TRUNCATE's already-working interval to do it. + // Moving checkpointing off s.mu entirely was considered and rejected: + // TRUNCATE's exclusive WAL lock is a SQLite-level constraint, not an + // app-level overcaution, so that would only trade a blocked goroutine for + // a SQLITE_BUSY retry loop of similar wall-clock cost. Re-measure after + // changing either number here. + go st.RunWALCheckpoint(ctx, 60*time.Second, 200*time.Second) go pc.Run(ctx, 2*time.Second) go poller.Run(ctx, time.Second) // Journal durability: fsync persisted batches, then ack each agent up to its diff --git a/coordinator/internal/store/store.go b/coordinator/internal/store/store.go index 46da71e..db2acd7 100644 --- a/coordinator/internal/store/store.go +++ b/coordinator/internal/store/store.go @@ -1957,18 +1957,19 @@ func (s *Store) RunIncrementalVacuum(ctx context.Context, every time.Duration) { // hold 33s -> 4.6s) but scaled sublinearly — a 15x shorter interval only // bought a 7x shorter hold, which means TRUNCATE has real fixed overhead // (the file-truncate step plus its fsync) that does not shrink just because -// less WAL content has accumulated. checkpointRunPassive (called every tick) -// is the fix for that floor: PASSIVE copies WAL content back to the main db -// file the same as TRUNCATE does, without needing TRUNCATE's exclusive -// file-shrinking lock, so it holds s.mu only as long as the copy itself -// takes — cheap and frequent. TRUNCATE (this method, still what -// WALCheckpoint calls directly) then runs far less often -// (walCheckpointTruncateEvery ticks), and by the time it does, the -// intervening PASSIVE calls have already drained most of the WAL content, so -// there is less left for TRUNCATE to redo and its own hold should be -// shorter still — not just called less often, but each call doing less work. -// See its call site in main.go for the current interval/ratio and the -// reasoning behind them. Called on a fixed schedule (RunWALCheckpoint) now +// less WAL content has accumulated. checkpointRunPassive (called on its own, +// independent cadence, see RunWALCheckpoint) is the fix for that floor: +// PASSIVE copies WAL content back to the main db file the same as TRUNCATE +// does, without needing TRUNCATE's exclusive file-shrinking lock, so it +// holds s.mu only as long as the copy itself takes — cheap and frequent. +// TRUNCATE (this method, still what WALCheckpoint calls directly) then runs +// far less often, and by the time it does, the intervening PASSIVE calls +// have already drained most of the WAL content, so there is less left for +// TRUNCATE to redo and its own hold should be shorter still — not just +// called less often, but each call doing less work. See RunWALCheckpoint's +// doc comment and its call site in main.go for the current cadences and the +// reasoning behind them (including why the two run on independent tickers +// rather than one coupled ratio). Called on a fixed schedule now // that wal_autocheckpoint is disabled at Open (see its comment there) — this // is what actually keeps the WAL from growing unbounded, just on a schedule // this process controls instead of one SQLite's internal page-count trigger @@ -2001,37 +2002,45 @@ func (s *Store) walCheckpoint(mode, label string) error { return nil } -// walCheckpointTruncateEvery: RunWALCheckpoint runs PASSIVE on every tick and -// promotes to TRUNCATE (which actually shrinks the WAL file on disk, see -// WALCheckpoint's doc comment) once every this-many ticks. -const walCheckpointTruncateEvery = 10 - // RunWALCheckpoint periodically checkpoints the WAL until ctx is done: a -// cheap PASSIVE checkpoint every tick to keep WAL content continuously -// drained, escalating to the more expensive TRUNCATE only every -// walCheckpointTruncateEvery ticks to reclaim the file's size on disk. See -// WALCheckpoint's doc comment for the full reasoning (this split is what -// brought the s.mu hold time down further than shortening the interval alone -// could) and the wal_autocheckpoint(0) comment in Open for why this exists: -// with SQLite's own auto-checkpoint trigger disabled, nothing else keeps the -// WAL bounded. -func (s *Store) RunWALCheckpoint(ctx context.Context, every time.Duration) { - t := time.NewTicker(every) - defer t.Stop() - tick := 0 +// cheap PASSIVE checkpoint every passiveEvery to keep WAL content +// continuously drained, escalating to the more expensive TRUNCATE every +// truncateEvery to reclaim the file's size on disk. See WALCheckpoint's doc +// comment for the full reasoning (this split is what brought the s.mu hold +// time down further than shortening one shared interval alone could) and the +// wal_autocheckpoint(0) comment in Open for why this exists: with SQLite's +// own auto-checkpoint trigger disabled, nothing else keeps the WAL bounded. +// +// The two cadences are independent, not one ticker with TRUNCATE riding +// every Nth PASSIVE tick (an earlier version did that): coupling them meant +// widening either cadence to fix one moved the other too. That mattered live +// — a 6-hour, 10-agent test at passiveEvery=20s/truncateEvery=200s (the +// coupled 1-tick/10-tick version) found PASSIVE's own median hold (3.4s) +// running *higher* than TRUNCATE's (2.95s), the opposite of what the split +// was for. At a 20s interval PASSIVE has very little WAL content to copy +// each call, so its hold time is dominated by fixed per-call overhead (lock +// dispatch, the PRAGMA itself) rather than actual copy work — running it 9x +// more often than truncateEvery was paying that fixed cost 9x without +// letting it amortize over more real work per call, the same floor +// TRUNCATE's own interval hit before this split existed. Decoupling lets +// passiveEvery widen (accumulate more real backlog per call, so the fixed +// cost matters less) independently of whatever truncateEvery is already +// tuned to. +func (s *Store) RunWALCheckpoint(ctx context.Context, passiveEvery, truncateEvery time.Duration) { + passiveT := time.NewTicker(passiveEvery) + defer passiveT.Stop() + truncateT := time.NewTicker(truncateEvery) + defer truncateT.Stop() for { select { case <-ctx.Done(): return - case <-t.C: - tick++ - var err error - if tick%walCheckpointTruncateEvery == 0 { - err = s.WALCheckpoint() - } else { - err = s.checkpointRunPassive() + case <-passiveT.C: + if err := s.checkpointRunPassive(); err != nil { + slog.Error("wal checkpoint failed", "err", err) } - if err != nil { + case <-truncateT.C: + if err := s.WALCheckpoint(); err != nil { slog.Error("wal checkpoint failed", "err", err) } } diff --git a/coordinator/internal/store/store_test.go b/coordinator/internal/store/store_test.go index e847577..9881de4 100644 --- a/coordinator/internal/store/store_test.go +++ b/coordinator/internal/store/store_test.go @@ -2479,14 +2479,15 @@ func TestCheckpointRunPassiveDoesNotShrinkWALFile(t *testing.T) { } } -// TestRunWALCheckpointTruncatesOnlyPeriodically: RunWALCheckpoint must not -// shrink the WAL file on every tick — only every walCheckpointTruncateEvery -// of them (see its doc comment for why: TRUNCATE's fixed per-call overhead -// means calling it as often as the cheap PASSIVE checkpoints would give back -// most of what shortening the interval bought). Drives exactly -// walCheckpointTruncateEvery-1 ticks (file must not have shrunk yet) then one -// more (file must have shrunk by then). -func TestRunWALCheckpointTruncatesOnlyPeriodically(t *testing.T) { +// TestRunWALCheckpointTruncatesOnItsOwnCadence: RunWALCheckpoint's +// PASSIVE and TRUNCATE cadences are independent tickers (not one ticker with +// TRUNCATE riding every Nth PASSIVE tick — see its doc comment for why that +// coupling was dropped: widening PASSIVE's interval to fix its fixed-cost +// problem would have forced widening TRUNCATE's too). This drives +// RunWALCheckpoint with a short PASSIVE interval and a longer TRUNCATE +// interval, and asserts the WAL file has NOT shrunk while only PASSIVE ticks +// have fired, then HAS shrunk once TRUNCATE's own interval has also elapsed. +func TestRunWALCheckpointTruncatesOnItsOwnCadence(t *testing.T) { path := filepath.Join(t.TempDir(), "state.db") s, err := Open(path) if err != nil { @@ -2513,39 +2514,39 @@ func TestRunWALCheckpointTruncatesOnlyPeriodically(t *testing.T) { t.Fatalf("WAL only %d bytes before checkpoint, too small to exercise this", before.Size()) } - // Drive one continuous RunWALCheckpoint (its own tick counter must not be - // restarted mid-test, or the Nth-tick assertion below is meaningless). - // The interval is generous relative to how long one checkpoint call - // actually takes (a few ms for 586 pages, more so for TRUNCATE) so ticks - // don't run behind schedule under load — this test previously flaked - // under -count=5 and under the full package's -race load at a tighter - // interval/margin. - const tickInterval = 150 * time.Millisecond + // PASSIVE fast enough to fire several times before TRUNCATE's own + // interval elapses; both generous relative to how long one checkpoint + // call actually takes (a few ms for 586 pages) so ticks don't run behind + // schedule under load — an earlier, tighter-margin version of this test + // flaked under -count=N and under the full package's -race load. + const passiveEvery = 50 * time.Millisecond + const truncateEvery = 400 * time.Millisecond ctx, cancel := context.WithCancel(context.Background()) defer cancel() - go s.RunWALCheckpoint(ctx, tickInterval) + go s.RunWALCheckpoint(ctx, passiveEvery, truncateEvery) - // Sample just before the Nth tick would fire: must still be PASSIVE-only. - time.Sleep(time.Duration(walCheckpointTruncateEvery-1) * tickInterval) + // Sample partway to truncateEvery: several PASSIVE ticks have fired, but + // TRUNCATE's own interval has not elapsed yet. + time.Sleep(truncateEvery - passiveEvery) mid, err := os.Stat(walPath) if err != nil { t.Fatal(err) } if mid.Size() < before.Size() { - t.Fatalf("WAL file already shrunk before tick %d (%d -> %d bytes): "+ - "TRUNCATE fired too early", walCheckpointTruncateEvery, before.Size(), mid.Size()) + t.Fatalf("WAL file already shrunk before TRUNCATE's own interval elapsed "+ + "(%d -> %d bytes)", before.Size(), mid.Size()) } - // Generous margin past the Nth tick, not a tight window right after it. - time.Sleep(3 * tickInterval) + // Generous margin past truncateEvery, not a tight window right after it. + time.Sleep(3 * truncateEvery) cancel() after, err := os.Stat(walPath) if err != nil { t.Fatal(err) } if after.Size() >= mid.Size() { - t.Fatalf("WAL file did not shrink by tick %d (%d bytes): "+ - "TRUNCATE should have fired by now", walCheckpointTruncateEvery, after.Size()) + t.Fatalf("WAL file did not shrink once TRUNCATE's interval elapsed (%d bytes): "+ + "TRUNCATE should have fired by now", after.Size()) } } @@ -2559,7 +2560,7 @@ func TestRunWALCheckpointStopsOnContextCancel(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) done := make(chan struct{}) go func() { - s.RunWALCheckpoint(ctx, time.Millisecond) + s.RunWALCheckpoint(ctx, time.Millisecond, time.Millisecond) close(done) }() cancel() diff --git a/docs/DESIGN-coordinator.md b/docs/DESIGN-coordinator.md index ce917bc..134cc47 100644 --- a/docs/DESIGN-coordinator.md +++ b/docs/DESIGN-coordinator.md @@ -319,13 +319,32 @@ journal_cursors (pass_id, agent_id, acked_seq) -- JournalBatch flow control WAL content back to the main db file, same as TRUNCATE, but needs no exclusive file-shrinking lock, so its `s.mu` hold is only as long as the copy itself) and a `TRUNCATE` checkpoint (still what `Store.WALCheckpoint` calls directly — existing - callers and tests are unaffected) only every `walCheckpointTruncateEvery` (10) - ticks, to reclaim the file's size on disk. By the time TRUNCATE runs, the - intervening PASSIVE calls have already drained most of what it would otherwise - have to copy, so its own hold should be shorter too, not just less frequent — - this is the fix for the fixed-cost floor the interval alone couldn't reach. + callers and tests are unaffected), to reclaim the file's size on disk. By the time + TRUNCATE runs, the intervening PASSIVE calls have already drained most of what it + would otherwise have to copy, so its own hold should be shorter too, not just less + frequent — this is the fix for the fixed-cost floor the interval alone couldn't + reach. And it worked on that axis: TRUNCATE's own median hold dropped further, to + 2.95s (max 8.7s), in a 6-hour, 10-agent re-test. + That same re-test surfaced a second-order effect the first version of the split + (one ticker, TRUNCATE riding every 10th PASSIVE tick) hadn't accounted for: + PASSIVE's own median hold (3.4s, 377 calls) came back *higher* than TRUNCATE's + (2.95s, 41 calls) — backwards from what the split was for, since PASSIVE needs no + exclusive lock at all. At a 20s PASSIVE interval there is very little real WAL + content to copy each call, so PASSIVE's hold is dominated by the same *fixed* + per-call overhead (lock dispatch, the `PRAGMA` itself) that limited TRUNCATE + before this split existed — just paid 9x as often as necessary, since the coupled + ticker forced PASSIVE's cadence to be exactly `truncateEvery`'s cadence divided by + the ratio. `RunWALCheckpoint` now runs PASSIVE and TRUNCATE on two independent + tickers (`passiveEvery`, `truncateEvery`) instead of one ticker with a tick-count + ratio, specifically so each cadence can be tuned without moving the other: PASSIVE + widened to 60s (accumulates more real backlog per call, amortizing its fixed cost + better) while TRUNCATE's already-working ~200s cadence is left alone. `TestCheckpointRunPassiveDoesNotShrinkWALFile` and - `TestRunWALCheckpointTruncatesOnlyPeriodically` pin the split. + `TestRunWALCheckpointTruncatesOnItsOwnCadence` pin the split and its independence. + The general lesson, consistent with every other `s.mu` finding in this file: two + competing costs (call frequency vs. per-call fixed overhead) rarely share one + optimal knob, and coupling them to save a line of code cost a real regression that + only a live re-measurement caught — re-measure again if either number here moves. - **Indexing discipline for high-write tables:** every predicate a hot-path query filters or joins on needs an index that actually serves it — not just "an index exists on the table." A single-writer store makes this load-bearing in a way a