Skip to content

dash: checkpoint() discards wal_checkpoint's busy result, so #115's WAL protection silently no-ops under load #166

Description

@amiddavid

DB.checkpoint() throws away the one piece of information that says whether the checkpoint happened, so the WAL-bloat protection added in #115 fails silently whenever a reader holds the lock — which is exactly when the WAL is growing.

The code

dash/store.go:642:

func (d *DB) checkpoint() {
	if d.path == "" || d.path == ":memory:" {
		return
	}
	_, _ = d.sql.Exec(`PRAGMA wal_checkpoint(TRUNCATE)`)
}

PRAGMA wal_checkpoint(TRUNCATE) does not return an error when it cannot run. It returns a row:
busy, log, checkpointed. busy=1 means another connection held a read lock, the WAL was not
truncated, and the call was a no-op. Exec discards the row, and the _ discards the error, so
there is no way — in a test or in production — to tell a checkpoint that ran from one that did not.

d.sql is a pooled *sql.DB shared with the recorder's writer goroutine and with every dashboard
and /metrics reader, so a concurrent reader is the normal case rather than the exception.

Why this is a production defect, not just a flaky test

The comment above janitorPass states the purpose precisely:

Checkpointing here, every pruneInterval, keeps the backlog small enough that neither this call nor
SQLite's own auto-checkpoint in between is ever slow.

and records what happens without it: a WAL bloated to ~40k pages made a single ordinary writer commit
take 5.5s, blocking a concurrent /metrics reader for 5.2s.

But the mechanism protecting against that is skipped, silently, whenever a reader is active — and
reader activity is correlated with the write traffic that grows the WAL. So on a busy deployment the
protection is least likely to work at the moment it is most needed, and nothing logs it. The
dashboard would simply hang on /metrics again, with no signal pointing here.

How it shows up

TestJanitorPassCheckpointsWAL (dash/janitor_checkpoint_test.go:80) fails intermittently:

janitor_checkpoint_test.go:80: janitorPass left the WAL at 6118232 bytes (want <= 65536):
it did not checkpoint on a pass with nothing to prune

The WAL size is identical in every failure (6,118,232 bytes) because the setup is deterministic;
what varies is whether a reader holds the lock when checkpoint() runs. That is the signature of a
real intermittent failure, not a noisy assertion — the test is right and the code is wrong.

Observed:

Where Result
CI build-test on two unrelated PRs (#161, #160) FAIL, same byte count
Same test, -race, 16-core box, while the box was otherwise busy 1 fail in 6
Same test, -race, clean main on a quiet box 10/10 pass
Alternating main vs an unrelated branch, matched load, 8 runs each 8/8 and 8/8 pass
CI on main recently green

So: load-sensitive, reproducible under contention, unrelated to any particular branch (nothing in
the PRs above opens a dash reader). It is not new — #115 introduced both the call and the test.

Fix options

  1. Read the result row and act on it — the smallest change that makes the failure visible:

    var busy, logFrames, checkpointed int
    err := d.sql.QueryRow(`PRAGMA wal_checkpoint(TRUNCATE)`).Scan(&busy, &logFrames, &checkpointed)
    if err != nil || busy != 0 {
        slog.Warn("dash: WAL checkpoint skipped, a reader held the lock",
            "busy", busy, "wal_frames", logFrames, "err", err)
    }

    On its own this fixes observability, not the WAL growth — but it turns a silent production
    failure into one an operator can see, and it gives the test something honest to assert.

  2. Retry with a short bounded backoff (a few attempts over, say, a second). Readers here are
    short-lived, so a retry will usually win, and the janitor runs on its own goroutine where a brief
    wait costs nothing.

  3. PRAGMA wal_checkpoint(PASSIVE) first, TRUNCATE opportunistically. PASSIVE always makes
    progress against the frames it can reach without blocking, so the backlog shrinks even when a
    full truncate is impossible; TRUNCATE then succeeds on a later pass.

  4. Set wal_autocheckpoint low enough that SQLite's own inline checkpoints stay cheap, and treat
    this call as best-effort. Changes the performance profile the fix(dash): stop /metrics hanging on an unchecked WAL backlog #115 comment measured, so it needs
    its own measurement.

My suggestion is (1) + (2): make it observable, then make it likely to succeed. (3) is a good
addition if the WAL is ever seen to grow despite retries.

I have not fixed this — it is dash's machinery and outside the PRs where I found it, and the fix
should come with a measurement of the WAL under retry rather than riding along in a distribution
change. Happy to take it if that is useful.

Found while adding the purego CI job (#161). Related: #162 and #163, two other tests whose
preconditions are hoped for rather than manufactured — this one is different in kind, because the
code, not the test, is at fault.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions