Checkpoint without waiting on readers and log a busy checkpoint (closes #102)

The 5-second checkpoint ran in TRUNCATE mode, which waits up to the
5-second busy timeout for every open read while holding the database
lock every batch write needs. It now runs in PASSIVE mode, which never
waits. A WAL file over 64 MiB instead gets one TRUNCATE checkpoint whose
wait for reads is capped at 500 ms and logged; it empties the file once
no read is open, and while reads follow one another with no pause it
can give up every time. A checkpoint that leaves part of the WAL
uncopied returns ErrCheckpointIncomplete, which the maintainer logs as
incomplete instead of completed. The writing connection's
journal_size_limit is 64 MiB.

Model: opus-5-5

internal/database/database.go

@@ -81,12 +81,14 @@ const (
 	sqliteHardHeapLimitBytes = 2147483648
 )
 
-// Settings that keep the WAL file small (see Checkpoint).
+// Settings that bound the WAL file's size once no read is open (see
+// Checkpoint).
 const (
 	// sqliteWALSizeLimitBytes (64 MiB) is the WAL file size past which
-	// Checkpoint truncates the file. It is also the journal_size_limit of the
-	// connection kept for writing: when SQLite starts the WAL again from the
-	// beginning, it cuts a larger WAL file down to this size.
+	// Checkpoint runs a TRUNCATE checkpoint. It is also the
+	// journal_size_limit of the connection kept for writing: when SQLite
+	// starts the WAL again from the beginning, it cuts a larger WAL file down
+	// to this size.
 	sqliteWALSizeLimitBytes = 67108864
 	// truncateBusyTimeoutMs is the busy timeout of the TRUNCATE checkpoint:
 	// the longest it waits for open reads, and so the longest it keeps batch
@@ -130,7 +132,8 @@ var (
 	// ErrCheckpointIncomplete is returned by Checkpoint when it left part of
 	// the WAL uncopied, or left a WAL file over sqliteWALSizeLimitBytes
 	// untruncated, because reads still needed the WAL or SQLite reported the
-	// checkpoint busy. A later checkpoint finishes the work.
+	// checkpoint busy. A later checkpoint that runs when no read is open
+	// finishes the work.
 	ErrCheckpointIncomplete = errors.New("WAL checkpoint incomplete")
 
 	errInvalidASN       = errors.New("invalid ASN")
@@ -2282,25 +2285,24 @@ func (d *Database) Analyze(ctx context.Context) error {
 	return nil
 }
 
-// Checkpoint copies the WAL into the database file and keeps the WAL file
-// small. It holds the database lock, so batch writes wait while it runs.
+// Checkpoint copies the WAL into the database file. It holds the database
+// lock, so batch writes wait while it runs.
 //
 // It runs a PASSIVE checkpoint, which never waits: it copies what no open read
-// still needs. That alone does not keep the file small: SQLite starts the WAL
-// again from the beginning only once a checkpoint has copied all of it and no
-// read that began before is still open, which never happens while reads keep
-// overlapping. So when the file is over sqliteWALSizeLimitBytes, Checkpoint
-// runs a TRUNCATE checkpoint instead, which waits for the reads that still need
-// the WAL, copies all of it and empties the file. That checkpoint waits at most
-// truncateBusyTimeoutMs, and it is logged with how long it took.
+// still needs, and leaves the file as large as it is. When the file is over
+// sqliteWALSizeLimitBytes, Checkpoint runs one TRUNCATE checkpoint instead,
+// which waits at most truncateBusyTimeoutMs for the open reads to end, then
+// copies all of the WAL and empties the file, or gives up. It is logged with
+// how long it took and whether it emptied the file.
 //
-// So while reads overlap, the WAL file stays under sqliteWALSizeLimitBytes
-// plus what batch writes add between two checkpoints, as long as no read stays
-// open longer than that wait. A longer read makes the TRUNCATE checkpoint give
-// up, and the file grows until a later one empties it.
+// So a file over the limit is emptied by the first Checkpoint that finds no
+// read open, at its start or at some moment of its wait. While reads follow
+// one another with no pause between them, every TRUNCATE checkpoint can give
+// up after its full wait, and the file can keep growing for as long as they
+// do.
 //
 // It returns ErrCheckpointIncomplete when it leaves part of the WAL uncopied,
-// or a file over the limit untruncated.
+// or a file over the limit not emptied.
 func (d *Database) Checkpoint(ctx context.Context) error {
 	d.lock("Checkpoint")
 	defer d.unlock()

internal/database/database_internal_test.go

@@ -72,24 +72,11 @@ const (
 	// waiting for it, may take while a reader is open: well under the busy
 	// timeout, which a checkpoint that waits for the reader takes.
 	readerCheckpointLimit = time.Second
-)
-
-// Parameters of the test of the WAL file's size while reads overlap.
-const (
-	// walFillStep is how much the test writes between two checkpoints.
-	walFillStep = sqliteWALSizeLimitBytes / 16
-	// walFillTotal is how much it writes in all: past sqliteWALSizeLimitBytes,
-	// and on until a WAL file that no checkpoint empties ends over walFillBound.
-	walFillTotal = sqliteWALSizeLimitBytes + 4*walFillStep
-	// walFillBound is the size the WAL file must stay under: the limit, plus
-	// the writes since the last checkpoint, plus one more step for SQLite's
-	// own pages besides the written data.
-	walFillBound = sqliteWALSizeLimitBytes + 2*walFillStep
-	// overlappingReads is how many reads the test keeps open at once.
-	overlappingReads = 2
-	// overlappingReadDuration is how long each read stays open: well under
-	// truncateBusyTimeoutMs, so the TRUNCATE checkpoint can wait for it.
-	overlappingReadDuration = 50 * time.Millisecond
+	// truncateCheckpointLimit is how long a checkpoint of a WAL file over
+	// sqliteWALSizeLimitBytes may take to give up while a reader is open: its
+	// wait for the reader plus a second, well under the busy timeout.
+	truncateCheckpointLimit = truncateBusyTimeoutMs*time.Millisecond +
+		time.Second
 )
 
 // Parameters for the prefix-length sample tests.
@@ -939,15 +926,14 @@ func TestCheckpointDoesNotWaitForReader(t *testing.T) {
 	}
 }
 
-// TestCheckpointKeepsWALSmallWhileReadsOverlap writes walFillTotal while
-// overlappingReads reads keep overlapping, so that one is open at every write,
-// and runs Checkpoint after every walFillStep, as the maintainer does between
-// batch writes. It checks that the WAL file stays under walFillBound and that
-// the writing connection has its busy timeout back afterwards. With only a
-// PASSIVE checkpoint, SQLite never started the WAL again from the beginning
-// while reads overlapped, and the file grew for as long as they did
-// (https://git.eeqj.de/sneak/routewatch/issues/102).
-func TestCheckpointKeepsWALSmallWhileReadsOverlap(t *testing.T) {
+// TestCheckpointEmptiesWALOnceNoReadIsOpen fills the WAL file past
+// sqliteWALSizeLimitBytes while the test holds a read open. With the read
+// open, it checks that Checkpoint gives up within truncateCheckpointLimit and
+// reports the checkpoint incomplete, and that a batch write still succeeds.
+// After the test closes the read, it checks that the next Checkpoint brings
+// the WAL file under the limit and gives the writing connection its busy
+// timeout back (https://git.eeqj.de/sneak/routewatch/issues/102).
+func TestCheckpointEmptiesWALOnceNoReadIsOpen(t *testing.T) {
 	t.Parallel()
 
 	db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New())
@@ -958,58 +944,65 @@ func TestCheckpointKeepsWALSmallWhileReadsOverlap(t *testing.T) {
 
 	ctx := t.Context()
 
-	// The test writes to a table of its own: each write replaces the one
-	// row's data with walFillStep of new random bytes, so the WAL grows by that
-	// much while the database file stays small. SQLite writes no page whose
-	// content stays the same, so the bytes must change. Like batch writes,
-	// the writes use the writing connection between the checkpoints.
-	_, err = db.writer.ExecContext(ctx,
-		"CREATE TABLE wal_fill (data BLOB); INSERT INTO wal_fill VALUES (NULL)")
+	reader, err := db.db.Conn(ctx)
 	if err != nil {
-		t.Fatalf("failed to create the table the test writes to: %v", err)
+		t.Fatalf("failed to open the reading connection: %v", err)
+	}
+	defer func() { _ = reader.Close() }()
+
+	// A plain BEGIN starts a transaction that only reads, unlike the BEGIN
+	// IMMEDIATE of _txlock. It keeps the snapshot its first read takes until
+	// it ends, so no checkpoint can copy what is written after that read.
+	_, err = reader.ExecContext(ctx, "BEGIN")
+	if err != nil {
+		t.Fatalf("failed to begin the read transaction: %v", err)
 	}
 
-	stop := make(chan struct{})
+	var routes int
 
-	var readers sync.WaitGroup
-
-	for i := range overlappingReads {
-		readers.Go(func() {
-			// Reader i starts i/overlappingReads of a read after the first,
-			// so that the reads overlap.
-			time.Sleep(time.Duration(i) * overlappingReadDuration /
-				overlappingReads)
-			keepReading(ctx, t, db, stop)
-		})
+	err = reader.QueryRowContext(ctx,
+		"SELECT count(*) FROM live_routes_v4").Scan(&routes)
+	if err != nil {
+		t.Fatalf("failed to read the live routes: %v", err)
 	}
 
-	defer func() {
-		close(stop)
-		readers.Wait()
-	}()
+	fillWALPastLimit(ctx, t, db)
 
-	for written := 0; written < walFillTotal; written += walFillStep {
-		_, err = db.writer.ExecContext(ctx,
-			"UPDATE wal_fill SET data = randomblob(?)", walFillStep)
-		if err != nil {
-			t.Fatalf("failed to write: %v", err)
-		}
+	started := time.Now()
 
-		wal, statErr := os.Stat(db.path + walFileSuffix)
-		if statErr != nil {
-			t.Fatalf("failed to read the WAL file's size: %v", statErr)
-		}
+	err = db.Checkpoint(ctx)
+	if !errors.Is(err, ErrCheckpointIncomplete) {
+		t.Errorf("Checkpoint = %v with a read open, want %v",
+			err, ErrCheckpointIncomplete)
+	}
 
-		if wal.Size() > walFillBound {
-			t.Fatalf("WAL file of %d bytes after writing %d with reads "+
-				"overlapping, want at most %d", wal.Size(), written+walFillStep,
-				walFillBound)
-		}
+	took := time.Since(started)
+	if took >= truncateCheckpointLimit {
+		t.Errorf("Checkpoint took %v with a read open, want under %v",
+			took, truncateCheckpointLimit)
+	}
 
-		err = db.Checkpoint(ctx)
-		if err != nil && !errors.Is(err, ErrCheckpointIncomplete) {
-			t.Fatalf("Checkpoint: %v", err)
-		}
+	err = db.UpsertLiveRouteBatch([]*LiveRoute{
+		mkV4Route(t, "192.0.2.0/24", lockTestASN, time.Now().UTC()),
+	})
+	if err != nil {
+		t.Errorf("batch write after Checkpoint gave up: %v", err)
+	}
+
+	_, err = reader.ExecContext(ctx, "ROLLBACK")
+	if err != nil {
+		t.Fatalf("failed to end the read transaction: %v", err)
+	}
+
+	err = db.Checkpoint(ctx)
+	if err != nil {
+		t.Errorf("Checkpoint with no read open: %v", err)
+	}
+
+	size := walFileSize(t, db)
+	if size >= sqliteWALSizeLimitBytes {
+		t.Errorf("WAL file of %d bytes after Checkpoint with no read open, "+
+			"want under %d", size, sqliteWALSizeLimitBytes)
 	}
 
 	busyTimeout := readPragma(ctx, t, db.writer, 0, "busy_timeout")
@@ -1019,57 +1012,40 @@ func TestCheckpointKeepsWALSmallWhileReadsOverlap(t *testing.T) {
 	}
 }
 
-// keepReading runs one read transaction after another on a connection of its
-// own, each open for overlappingReadDuration, until stop is closed.
-func keepReading(
-	ctx context.Context, t *testing.T, db *Database, stop <-chan struct{},
-) {
+// fillWALPastLimit writes sqliteWALSizeLimitBytes of random bytes to a table
+// of the test's own, which with SQLite's page and frame headers leaves the WAL
+// file of db over the limit, and checks that it does.
+func fillWALPastLimit(ctx context.Context, t *testing.T, db *Database) {
 	t.Helper()
 
-	conn, err := db.db.Conn(ctx)
+	_, err := db.writer.ExecContext(ctx, "CREATE TABLE wal_fill (data BLOB)")
 	if err != nil {
-		t.Errorf("failed to open a reading connection: %v", err)
-
-		return
+		t.Fatalf("failed to create the table the test writes to: %v", err)
 	}
-	defer func() { _ = conn.Close() }()
 
-	for {
-		select {
-		case <-stop:
-			return
-		default:
-		}
-
-		// A plain BEGIN starts a transaction that only reads, unlike the
-		// BEGIN IMMEDIATE of _txlock. It keeps the snapshot its first read
-		// takes until it ends.
-		_, err = conn.ExecContext(ctx, "BEGIN")
-		if err != nil {
-			t.Errorf("failed to begin a read transaction: %v", err)
-
-			return
-		}
-
-		var rows int
-
-		err = conn.QueryRowContext(ctx, "SELECT count(*) FROM wal_fill").
-			Scan(&rows)
-		if err != nil {
-			t.Errorf("failed to read: %v", err)
-
-			return
-		}
-
-		time.Sleep(overlappingReadDuration)
-
-		_, err = conn.ExecContext(ctx, "ROLLBACK")
-		if err != nil {
-			t.Errorf("failed to end a read transaction: %v", err)
-
-			return
-		}
+	_, err = db.writer.ExecContext(ctx,
+		"INSERT INTO wal_fill VALUES (randomblob(?))", sqliteWALSizeLimitBytes)
+	if err != nil {
+		t.Fatalf("failed to fill the WAL: %v", err)
 	}
+
+	size := walFileSize(t, db)
+	if size <= sqliteWALSizeLimitBytes {
+		t.Fatalf("WAL file of %d bytes after the test's write, want over %d",
+			size, sqliteWALSizeLimitBytes)
+	}
+}
+
+// walFileSize returns the size of the WAL file of db.
+func walFileSize(t *testing.T, db *Database) int64 {
+	t.Helper()
+
+	wal, err := os.Stat(db.path + walFileSuffix)
+	if err != nil {
+		t.Fatalf("failed to read the WAL file's size: %v", err)
+	}
+
+	return wal.Size()
 }
 
 // TestGetRandomPrefixesByLengthListsPrefixOnce stores one prefix of each