Log datastore metrics

psiphon/controller.go

@@ -1796,6 +1796,11 @@ func (controller *Controller) stopEstablishing() {
 
 	emitMemoryMetrics()
 	DoGarbageCollection()
+
+	// Record datastore metrics after establishment, the phase which generates
+	// the bulk of all datastore transactions: iterating over server entries,
+	// storing new server entries, etc.
+	emitDatastoreMetrics()
 }
 
 // establishCandidateGenerator populates the candidate queue with server entries

psiphon/dataStore.go

@@ -192,6 +192,18 @@ func CloseDataStore() {
 	activeDatastoreDB = nil
 }
 
+// GetDataStoreMetrics returns a string logging datastore metrics.
+func GetDataStoreMetrics() string {
+	datastoreMutex.RLock()
+	defer datastoreMutex.RUnlock()
+
+	if activeDatastoreDB == nil {
+		return ""
+	}
+
+	return activeDatastoreDB.getDataStoreMetrics()
+}
+
 // datastoreView runs a read-only transaction, making datastore buckets and
 // values available to the supplied function.
 //

psiphon/dataStore_badger.go

@@ -95,6 +95,11 @@ func (db *datastoreDB) close() error {
 	return db.badgerDB.Close()
 }
 
+func (db *datastoreDB) getDataStoreMetrics() string {
+	// TODO: report metrics
+	return ""
+}
+
 func (db *datastoreDB) view(fn func(tx *datastoreTx) error) error {
 	return db.badgerDB.View(
 		func(tx *badger.Txn) error {

psiphon/dataStore_bolt.go

@@ -24,6 +24,7 @@ package psiphon
 
 import (
 	std_errors "errors"
+	"fmt"
 	"os"
 	"path/filepath"
 	"runtime/debug"
@@ -31,6 +32,7 @@ import (
 	"time"
 
 	"github.com/Psiphon-Labs/bolt"
+	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common/errors"
 )
 
@@ -40,6 +42,7 @@ const (
 
 type datastoreDB struct {
 	boltDB   *bolt.DB
+	filename string
 	isFailed int32
 }
 
@@ -125,6 +128,14 @@ func tryDatastoreOpenDB(
 		os.Remove(filename)
 	}
 
+	// A typical Psiphon datastore will not have a large, fragmented freelist.
+	// For this reason, we're not setting FreelistType to FreelistMapType or
+	// enabling NoFreelistSync. The latter option has a trade-off of slower
+	// start up time.
+	//
+	// Monitor freelist stats in DataStoreMetrics in diagnostics and consider
+	// setting these options if necessary.
+
 	newDB, err := bolt.Open(filename, 0600, &bolt.Options{Timeout: 1 * time.Second})
 	if err != nil {
 		return nil, errors.Trace(err)
@@ -190,7 +201,10 @@ func tryDatastoreOpenDB(
 		return nil, errors.Trace(err)
 	}
 
-	return &datastoreDB{boltDB: newDB}, nil
+	return &datastoreDB{
+		boltDB:   newDB,
+		filename: filename,
+	}, nil
 }
 
 var errDatastoreFailed = std_errors.New("datastore has failed")
@@ -215,6 +229,22 @@ func (db *datastoreDB) close() error {
 	return db.boltDB.Close()
 }
 
+func (db *datastoreDB) getDataStoreMetrics() string {
+	fileSize := int64(0)
+	fileInfo, err := os.Stat(db.filename)
+	if err == nil {
+		fileSize = fileInfo.Size()
+	}
+	stats := db.boltDB.Stats()
+	return fmt.Sprintf("filesize %s | freepages %d | freealloc %s | txcount %d | writes %d | writetime %s",
+		common.FormatByteCount(uint64(fileSize)),
+		stats.FreePageN,
+		common.FormatByteCount(uint64(stats.FreeAlloc)),
+		stats.TxN,
+		stats.TxStats.Write,
+		stats.TxStats.WriteTime)
+}
+
 func (db *datastoreDB) view(fn func(tx *datastoreTx) error) (reterr error) {
 
 	// Any bolt function that performs mmap buffer accesses can raise SIGBUS due

psiphon/dataStore_files.go

@@ -134,6 +134,11 @@ func (db *datastoreDB) close() error {
 	return nil
 }
 
+func (db *datastoreDB) getDataStoreMetrics() string {
+	// TODO: report metrics
+	return ""
+}
+
 func (db *datastoreDB) view(fn func(tx *datastoreTx) error) error {
 	db.lock.RLock()
 	defer db.lock.RUnlock()

psiphon/utils.go

@@ -323,6 +323,10 @@ func emitMemoryMetrics() {
 		common.FormatByteCount(memStats.TotalAlloc))
 }
 
+func emitDatastoreMetrics() {
+	NoticeInfo("Datastore metrics at %s: %s", stacktrace.GetParentFunctionName(), GetDataStoreMetrics())
+}
+
 func DoGarbageCollection() {
 	debug.SetGCPercent(5)
 	debug.FreeOSMemory()