From 52eba8049a032877af478f86968a4c42240fb145 Mon Sep 17 00:00:00 2001 From: Philip O'Toole Date: Sun, 28 Jan 2024 22:06:07 -0500 Subject: [PATCH 1/2] Remove metrics --- db/db_checkpoint_test.go | 80 +++++++++++++++++++++++++++++++++++----- store/store.go | 26 +++---------- 2 files changed, 76 insertions(+), 30 deletions(-) diff --git a/db/db_checkpoint_test.go b/db/db_checkpoint_test.go index 862af48a..f76dd890 100644 --- a/db/db_checkpoint_test.go +++ b/db/db_checkpoint_test.go @@ -72,19 +72,13 @@ func Test_WALDatabaseCheckpoint_RestartTruncate(t *testing.T) { } } - walPreBytes, err := os.ReadFile(db.WALPath()) - if err != nil { - t.Fatalf("failed to read wal file: %s", err.Error()) - } + walPreBytes := mustReadBytes(db.WALPath()) if err := db.Checkpoint(CheckpointRestart); err != nil { t.Fatalf("failed to checkpoint database: %s", err.Error()) } - walPostBytes, err := os.ReadFile(db.WALPath()) - if err != nil { - t.Fatalf("failed to read wal file: %s", err.Error()) - } + walPostBytes := mustReadBytes(db.WALPath()) if !bytes.Equal(walPreBytes, walPostBytes) { - t.Fatalf("wal files should be identical after checkpoint restart") + t.Fatalf("wal file should be unchanged after checkpoint restart") } // query the data to make sure all is well. @@ -117,6 +111,8 @@ func Test_WALDatabaseCheckpoint_RestartTruncate(t *testing.T) { } } +// Test_WALDatabaseCheckpoint_RestartTimeout tests that a restart checkpoint +// does time out as expected if there is a long running read. func Test_WALDatabaseCheckpoint_RestartTimeout(t *testing.T) { path := mustTempFile() defer os.Remove(path) @@ -154,12 +150,78 @@ func Test_WALDatabaseCheckpoint_RestartTimeout(t *testing.T) { t.Fatalf("expected %s, got %s", exp, got) } + if err := db.CheckpointWithTimeout(CheckpointRestart, 250*time.Millisecond); err == nil { + t.Fatal("expected error due to failure to checkpoint") + } + + blockingDB.Close() + if err := db.CheckpointWithTimeout(CheckpointRestart, 250*time.Millisecond); err != nil { + t.Fatalf("failed to checkpoint database: %s", err.Error()) + } +} + +// Test_WALDatabaseCheckpoint_TruncateTimeout tests that a truncate checkpoint +// does time out as expected if there is a long running read. It also confirms +// that the WAL file is not modified as a result of this failure. +func Test_WALDatabaseCheckpoint_TruncateTimeout(t *testing.T) { + path := mustTempFile() + defer os.Remove(path) + db, err := Open(path, false, true) + if err != nil { + t.Fatalf("failed to open database in WAL mode: %s", err.Error()) + } + defer db.Close() + + _, err = db.ExecuteStringStmt(`CREATE TABLE foo (id INTEGER NOT NULL PRIMARY KEY, name TEXT)`) + if err != nil { + t.Fatalf("failed to execute on single node: %s", err.Error()) + } + for i := 0; i < 50; i++ { + _, err := db.ExecuteStringStmt(`INSERT INTO foo(name) VALUES("fiona")`) + if err != nil { + t.Fatalf("failed to execute INSERT on single node: %s", err.Error()) + } + } + + preWALBytes := mustReadBytes(db.WALPath()) + blockingDB, err := Open(path, false, true) + if err != nil { + t.Fatalf("failed to open blocking database in WAL mode: %s", err.Error()) + } + defer blockingDB.Close() + _, err = blockingDB.QueryStringStmt(`BEGIN TRANSACTION`) + if err != nil { + t.Fatalf("failed to execute query on single node: %s", err.Error()) + } + rows, err := blockingDB.QueryStringStmt(`SELECT COUNT(*) FROM foo`) + if err != nil { + t.Fatalf("failed to execute query on single node: %s", err.Error()) + } + if exp, got := `[{"columns":["COUNT(*)"],"types":["integer"],"values":[[50]]}]`, asJSON(rows); exp != got { + t.Fatalf("expected %s, got %s", exp, got) + } + if err := db.CheckpointWithTimeout(CheckpointTruncate, 250*time.Millisecond); err == nil { t.Fatal("expected error due to failure to checkpoint") } + postWALBytes := mustReadBytes(db.WALPath()) + if !bytes.Equal(preWALBytes, postWALBytes) { + t.Fatalf("wal file should be unchanged after checkpoint failure") + } blockingDB.Close() if err := db.CheckpointWithTimeout(CheckpointTruncate, 250*time.Millisecond); err != nil { t.Fatalf("failed to checkpoint database: %s", err.Error()) } + if mustFileSize(db.WALPath()) != 0 { + t.Fatalf("wal file should be zero length after checkpoint truncate") + } +} + +func mustReadBytes(path string) []byte { + b, err := os.ReadFile(path) + if err != nil { + panic(err) + } + return b } diff --git a/store/store.go b/store/store.go index 420de276..96ec3a3b 100644 --- a/store/store.go +++ b/store/store.go @@ -117,7 +117,6 @@ const ( numSnapshotsFull = "num_snapshots_full" numSnapshotsIncremental = "num_snapshots_incremental" numFullCheckpointFailed = "num_full_checkpoint_failed" - numWALCheckpointRestartFailed = "num_wal_checkpoint_restart_failed" numWALCheckpointTruncateFailed = "num_wal_checkpoint_truncate_failed" numAutoVacuums = "num_auto_vacuums" numAutoVacuumsFailed = "num_auto_vacuums_failed" @@ -141,7 +140,6 @@ const ( numRemovedBeforeJoins = "num_removed_before_joins" numDBStatsErrors = "num_db_stats_errors" snapshotCreateDuration = "snapshot_create_duration" - snapshotCreateChkRestartDuration = "snapshot_create_chk_restart_duration" snapshotCreateChkTruncateDuration = "snapshot_create_chk_truncate_duration" snapshotCreateWALCompactDuration = "snapshot_create_wal_compact_duration" snapshotPersistDuration = "snapshot_persist_duration" @@ -174,7 +172,6 @@ func ResetStats() { stats.Add(numSnapshotsFull, 0) stats.Add(numSnapshotsIncremental, 0) stats.Add(numFullCheckpointFailed, 0) - stats.Add(numWALCheckpointRestartFailed, 0) stats.Add(numWALCheckpointTruncateFailed, 0) stats.Add(numAutoVacuums, 0) stats.Add(numAutoVacuumsFailed, 0) @@ -198,7 +195,6 @@ func ResetStats() { stats.Add(numRemovedBeforeJoins, 0) stats.Add(numDBStatsErrors, 0) stats.Add(snapshotCreateDuration, 0) - stats.Add(snapshotCreateChkRestartDuration, 0) stats.Add(snapshotCreateChkTruncateDuration, 0) stats.Add(snapshotCreateWALCompactDuration, 0) stats.Add(snapshotPersistDuration, 0) @@ -1941,18 +1937,6 @@ func (s *Store) fsmSnapshot() (fSnap raft.FSMSnapshot, retErr error) { compactedBuf := bytes.NewBuffer(nil) var err error if pathExistsWithData(s.walPath) { - // Attempt to checkpoint everything into the main database file. Only - // if this works should we bother to compact-scan the WAL. It's possible - // it fails if some query is in progress. If it fails, return an error - // and Raft will retry later. But if it succeeds it means that all readers - // are reading from the main database file. - chkRStartTime := time.Now() - if err := s.db.Checkpoint(sql.CheckpointRestart); err != nil { - stats.Add(numWALCheckpointRestartFailed, 1) - return nil, err - } - stats.Get(snapshotCreateChkRestartDuration).(*expvar.Int).Set(time.Since(chkRStartTime).Milliseconds()) - compactStartTime := time.Now() // Read a compacted version of the WAL into memory, and write it // to the Snapshot store. @@ -1975,10 +1959,9 @@ func (s *Store) fsmSnapshot() (fSnap raft.FSMSnapshot, retErr error) { walFD.Close() // We need it closed for the next step. stats.Get(snapshotCreateWALCompactDuration).(*expvar.Int).Set(time.Since(compactStartTime).Milliseconds()) - // Clean-up by truncating the WAL. This should be fast because all the pages - // have been checkpointed into the main database file, and writes are - // blocked during this process by Raft. In otherwords, the WAL file should - // be unchanged. + // Now that we're written a (compacted) copy of the WAL to the Snapshot, + // we can truncate the WAL. We use truncate mode so that the next WAL + // contains just changes since the this snapshot. walSz, err := fileSize(s.walPath) if err != nil { return nil, err @@ -1986,7 +1969,8 @@ func (s *Store) fsmSnapshot() (fSnap raft.FSMSnapshot, retErr error) { chkTStartTime := time.Now() if err := s.db.Checkpoint(sql.CheckpointTruncate); err != nil { stats.Add(numWALCheckpointTruncateFailed, 1) - return nil, fmt.Errorf("failed to truncate WAL: %s", err.Error()) + return nil, fmt.Errorf("snapshot can't complete due to WAL checkpoint failure (will retry): %s", + err.Error()) } stats.Get(snapshotCreateChkTruncateDuration).(*expvar.Int).Set(time.Since(chkTStartTime).Milliseconds()) stats.Get(snapshotWALSize).(*expvar.Int).Set(int64(compactedBuf.Len())) From 6b0c13f6a69867293c5305b18b5b67c6b9d0cc06 Mon Sep 17 00:00:00 2001 From: Philip O'Toole Date: Sun, 28 Jan 2024 22:07:20 -0500 Subject: [PATCH 2/2] Remove Restart Checkpoint operation A Truncate checkpoint is not faster with an initial Restart, in fact it's much slower. --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index ee54f5a1..edc63cb7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,7 @@ ### Implementation changes and bug fixes - [PR #1638](https://github.com/rqlite/rqlite/pull/1638): More Snapshotting metrics. - [PR #1639](https://github.com/rqlite/rqlite/pull/1639): Reuse Session and S3 manager when working with AWS S3. Thanks @mauri870 +- [PR #1640](https://github.com/rqlite/rqlite/pull/1640): Remove Restart checkpoint, tests show it's not an optimization. ## 8.18.2 (January 27th 2024) ### Implementation changes and bug fixes