Log at DB level if open times are higher

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
+	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)
+	return fileSize(db.path)
-	if err != nil {
-		return 0, err
-	}
-	return fi.Size(), nil
 }
 
 // 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)
+	sz, err := fileSize(db.walPath)
-	if err != nil {
+	if err == nil || (err != nil && os.IsNotExist(err)) {
-		if !os.IsNotExist(err) {
+		return sz, nil
-			return 0, err
-		}
-		return 0, 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
+}

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
 		}
 	}
 }

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
+	logger *log.Logger
 }
 
 // NewSnapshot creates a new snapshot.
 func NewSnapshot(rc io.ReadCloser) *Snapshot {
 	return &Snapshot{
 		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
 	}

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()