From 4988c299517b4ea7b8445985b1e6fe86a2272b06 Mon Sep 17 00:00:00 2001 From: Philip O'Toole Date: Sun, 17 Dec 2023 09:30:38 -0500 Subject: [PATCH] Log at DB level if open times are higher --- db/db.go | 57 +++++++++++++++++++++++++++++++++----------- progress/progress.go | 6 ----- snapshot/snapshot.go | 17 ++++++++++--- store/store.go | 2 +- 4 files changed, 58 insertions(+), 24 deletions(-) diff --git a/db/db.go b/db/db.go index a9a2a2fa..ff915934 100644 --- a/db/db.go +++ b/db/db.go @@ -10,6 +10,7 @@ import ( "expvar" "fmt" "io" + "log" "os" "path/filepath" "strconv" @@ -22,11 +23,13 @@ import ( const ( SQLiteHeaderSize = 32 - - bkDelay = 250 + bkDelay = 250 + sizeAtOpenWarn = 500 * 1024 * 1024 + durToOpenLog = 2 * time.Second ) const ( + openDuration = "open_duration_ms" numCheckpoints = "checkpoints" numCheckpointErrors = "checkpoint_errors" numCheckpointedPages = "checkpointed_pages" @@ -63,6 +66,7 @@ func init() { // ResetStats resets the expvar stats for this module. Mostly for test purposes. func ResetStats() { stats.Init() + stats.Add(openDuration, 0) stats.Add(numCheckpoints, 0) stats.Add(numCheckpointErrors, 0) stats.Add(numCheckpointedPages, 0) @@ -90,6 +94,8 @@ type DB struct { rwDSN string // DSN used for read-write connection roDSN string // DSN used for read-only connections + + logger *log.Logger } // PoolStats represents connection pool statistics @@ -311,6 +317,24 @@ func ReplayWAL(path string, wals []string, deleteMode bool) error { // Open opens a file-based database, creating it if it does not exist. After this // function returns, an actual SQLite file will always exist. func Open(dbPath string, fkEnabled, wal bool) (*DB, error) { + logger := log.New(log.Writer(), "[db] ", log.LstdFlags) + startTime := time.Now() + defer func() { + dur := time.Since(startTime) + if dur > durToOpenLog { + logger.Printf("opened database %s in %s", dbPath, time.Since(startTime)) + } + stats.Get(openDuration).(*expvar.Int).Set(time.Since(startTime).Milliseconds()) + }() + + sz, err := fileSize(dbPath) + if err != nil { + return nil, err + } + if sz > sizeAtOpenWarn { + logger.Printf("database file is %d bytes, SQLite may require an extended time to open", sz) + } + rwDSN := fmt.Sprintf("file:%s?_fk=%s", dbPath, strconv.FormatBool(fkEnabled)) rwDB, err := sql.Open("sqlite3", rwDSN) if err != nil { @@ -368,6 +392,7 @@ func Open(dbPath string, fkEnabled, wal bool) (*DB, error) { roDB: roDB, rwDSN: rwDSN, roDSN: roDSN, + logger: logger, }, nil } @@ -441,11 +466,7 @@ func (db *DB) Size() (int64, error) { // FileSize returns the size of the SQLite file on disk. If running in // on-memory mode, this function returns 0. func (db *DB) FileSize() (int64, error) { - fi, err := os.Stat(db.path) - if err != nil { - return 0, err - } - return fi.Size(), nil + return fileSize(db.path) } // WALSize returns the size of the SQLite WAL file on disk. If running in @@ -454,14 +475,11 @@ func (db *DB) WALSize() (int64, error) { if !db.wal { return 0, nil } - fi, err := os.Stat(db.walPath) - if err != nil { - if !os.IsNotExist(err) { - return 0, err - } - return 0, nil + sz, err := fileSize(db.walPath) + if err == nil || (err != nil && os.IsNotExist(err)) { + return sz, nil } - return fi.Size(), nil + return 0, err } // Checkpoint checkpoints the WAL file. If the WAL file is not enabled, this @@ -1498,3 +1516,14 @@ func containsEmptyType(slice []string) bool { } return false } + +func fileSize(path string) (int64, error) { + stat, err := os.Stat(path) + if err != nil { + return 0, err + } + if stat.Mode().IsDir() { + return 0, fmt.Errorf("not a file") + } + return stat.Size(), nil +} diff --git a/progress/progress.go b/progress/progress.go index 8dd7be1c..e452fdf3 100644 --- a/progress/progress.go +++ b/progress/progress.go @@ -106,18 +106,12 @@ func (cm *CountingMonitor) run(ctx context.Context) { ticker := time.NewTicker(countingMonitorInterval) defer ticker.Stop() - - ranOnce := false for { select { case <-ctx.Done(): - if !ranOnce { - cm.runOnce() - } return case <-ticker.C: cm.runOnce() - ranOnce = true } } } diff --git a/snapshot/snapshot.go b/snapshot/snapshot.go index 599e4137..e848794d 100644 --- a/snapshot/snapshot.go +++ b/snapshot/snapshot.go @@ -3,20 +3,24 @@ package snapshot import ( "expvar" "io" + "log" "time" "github.com/hashicorp/raft" + "github.com/rqlite/rqlite/progress" ) // Snapshot represents a snapshot of the database state. type Snapshot struct { - rc io.ReadCloser + rc io.ReadCloser + logger *log.Logger } // NewSnapshot creates a new snapshot. func NewSnapshot(rc io.ReadCloser) *Snapshot { return &Snapshot{ - rc: rc, + rc: rc, + logger: log.New(log.Writer(), "[snapshot] ", log.LstdFlags), } } @@ -25,7 +29,14 @@ func (s *Snapshot) Persist(sink raft.SnapshotSink) error { defer s.rc.Close() startT := time.Now() - n, err := io.Copy(sink, s.rc) + cw := progress.NewCountingWriter(sink) + cm := progress.StartCountingMonitor(func(n int64) { + s.logger.Printf("persisted %d bytes", n) + }, cw) + n, err := func() (int64, error) { + defer cm.StopAndWait() + return io.Copy(cw, s.rc) + }() if err != nil { return err } diff --git a/store/store.go b/store/store.go index 46754486..4487b9be 100644 --- a/store/store.go +++ b/store/store.go @@ -1286,7 +1286,7 @@ func (s *Store) ReadFrom(r io.Reader) (int64, error) { cw := progress.NewCountingWriter(f) cm := progress.StartCountingMonitor(func(n int64) { - s.logger.Printf("installed %d bytes", n) + s.logger.Printf("boot process installed %d bytes", n) }, cw) n, err := func() (int64, error) { defer cm.StopAndWait()