Merge pull request #112 from benbjohnson/perf-stats

Add performance counters.

bucket.go

@@ -65,6 +65,10 @@ func (b *Bucket) Writable() bool {
 // The cursor is only valid as long as the transaction is open.
 // Do not use a cursor after the transaction is closed.
 func (b *Bucket) Cursor() *Cursor {
+	// Update transaction statistics.
+	b.tx.stats.CursorCount++
+
+	// Allocate and return a cursor.
 	return &Cursor{
 		tx:    b.tx,
 		root:  b.root,

bucket_test.go

@@ -341,7 +341,6 @@ func TestBucketPutSingle(t *testing.T) {
 			}
 		})
 
-		fmt.Fprint(os.Stderr, ".")
 		index++
 		return true
 	}
@@ -385,7 +384,6 @@ func TestBucketPutMultiple(t *testing.T) {
 				return nil
 			})
 		})
-		fmt.Fprint(os.Stderr, ".")
 		return true
 	}
 	if err := quick.Check(f, qconfig()); err != nil {
@@ -442,7 +440,6 @@ func TestBucketDeleteQuick(t *testing.T) {
 				})
 			}
 		})
-		fmt.Fprint(os.Stderr, ".")
 		return true
 	}
 	if err := quick.Check(f, qconfig()); err != nil {

db.go

@@ -40,6 +40,7 @@ type DB struct {
 	rwtx     *Tx
 	txs      []*Tx
 	freelist *freelist
+	stats    Stats
 
 	rwlock   sync.Mutex   // Allows only one writer at a time.
 	metalock sync.Mutex   // Protects meta page access.
@@ -374,6 +375,9 @@ func (db *DB) removeTx(t *Tx) {
 			break
 		}
 	}
+
+	// Merge statistics.
+	db.stats.TxStats.add(&t.stats)
 }
 
 // Update executes a function within the context of a read-write managed transaction.
@@ -490,32 +494,12 @@ func (db *DB) CopyFile(path string, mode os.FileMode) error {
 	return f.Close()
 }
 
-// Stat retrieves stats on the database and its page usage.
-// Returns an error if the database is not open.
-func (db *DB) Stat() (*Stat, error) {
-	// Obtain meta & mmap locks.
+// Stats retrieves ongoing performance stats for the database.
+// This is only updated when a transaction closes.
+func (db *DB) Stats() Stats {
 	db.metalock.Lock()
-	db.mmaplock.RLock()
-
-	var s = &Stat{
-		MmapSize: len(db.data),
-		TxCount:  len(db.txs),
-	}
-
-	// Release locks.
-	db.mmaplock.RUnlock()
-	db.metalock.Unlock()
-
-	err := db.Update(func(t *Tx) error {
-		s.PageCount = int(t.meta.pgid)
-		s.FreePageCount = len(db.freelist.all())
-		s.PageSize = db.pageSize
-		return nil
-	})
-	if err != nil {
-		return nil, err
-	}
-	return s, nil
+	defer db.metalock.Unlock()
+	return db.stats
 }
 
 // Check performs several consistency checks on the database.
@@ -625,25 +609,20 @@ func (db *DB) allocate(count int) (*page, error) {
 	return p, nil
 }
 
-// Stat represents stats on the database such as free pages and sizes.
-type Stat struct {
-	// PageCount is the total number of allocated pages. This is a high water
-	// mark in the database that represents how many pages have actually been
-	// used. This will be smaller than the MmapSize / PageSize.
-	PageCount int
-
-	// FreePageCount is the total number of pages which have been previously
-	// allocated but are no longer used.
-	FreePageCount int
-
-	// PageSize is the size, in bytes, of individual database pages.
-	PageSize int
+// Stats represents statistics about the database.
+type Stats struct {
+	TxStats TxStats // global, ongoing stats.
+}
 
-	// MmapSize is the mmap-allocated size of the data file. When the data file
-	// grows beyond this size, the database will obtain a lock on the mmap and
-	// resize it.
-	MmapSize int
+// Sub calculates and returns the difference between two sets of database stats.
+// This is useful when obtaining stats at two different points and time and
+// you need the performance counters that occurred within that time span.
+func (s *Stats) Sub(other *Stats) Stats {
+	var diff Stats
+	diff.TxStats = s.TxStats.Sub(&other.TxStats)
+	return diff
+}
 
-	// TxCount is the total number of reader transactions.
-	TxCount int
+func (s *Stats) add(other *Stats) {
+	s.TxStats.add(&other.TxStats)
 }

db_test.go

@@ -2,17 +2,23 @@ package bolt
 
 import (
 	"errors"
+	"flag"
+	"fmt"
 	"io/ioutil"
 	"math/rand"
 	"os"
+	"regexp"
 	"strconv"
 	"strings"
 	"testing"
+	"time"
 	"unsafe"
 
 	"github.com/stretchr/testify/assert"
 )
 
+var statsFlag = flag.Bool("stats", false, "show performance stats")
+
 // Ensure that a database can be opened without error.
 func TestOpen(t *testing.T) {
 	f, _ := ioutil.TempFile("", "bolt-")
@@ -214,55 +220,6 @@ func TestDBCopyFile(t *testing.T) {
 	})
 }
 
-// Ensure the database can return stats about itself.
-func TestDBStat(t *testing.T) {
-	withOpenDB(func(db *DB, path string) {
-		db.Update(func(tx *Tx) error {
-			tx.CreateBucket("widgets")
-			b := tx.Bucket("widgets")
-			for i := 0; i < 10000; i++ {
-				b.Put([]byte(strconv.Itoa(i)), []byte(strconv.Itoa(i)))
-			}
-			return nil
-		})
-
-		// Delete some keys.
-		db.Update(func(tx *Tx) error {
-			return tx.Bucket("widgets").Delete([]byte("10"))
-		})
-		db.Update(func(tx *Tx) error {
-			return tx.Bucket("widgets").Delete([]byte("1000"))
-		})
-
-		// Open some readers.
-		t0, _ := db.Begin(false)
-		t1, _ := db.Begin(false)
-		t2, _ := db.Begin(false)
-		t2.Rollback()
-
-		// Obtain stats.
-		stat, err := db.Stat()
-		assert.NoError(t, err)
-		assert.Equal(t, 127, stat.PageCount)
-		assert.Equal(t, 4, stat.FreePageCount)
-		assert.Equal(t, 4096, stat.PageSize)
-		assert.Equal(t, 4194304, stat.MmapSize)
-		assert.Equal(t, 2, stat.TxCount)
-
-		// Close readers.
-		t0.Rollback()
-		t1.Rollback()
-	})
-}
-
-// Ensure the getting stats on a closed database returns an error.
-func TestDBStatWhileClosed(t *testing.T) {
-	var db DB
-	stat, err := db.Stat()
-	assert.Equal(t, err, ErrDatabaseNotOpen)
-	assert.Nil(t, stat)
-}
-
 // Ensure that an error is returned when a database write fails.
 func TestDBWriteFail(t *testing.T) {
 	t.Skip("pending") // TODO(benbjohnson)
@@ -384,6 +341,11 @@ func withOpenDB(fn func(*DB, string)) {
 		defer db.Close()
 		fn(db, path)
 
+		// Log statistics.
+		if *statsFlag {
+			logStats(db)
+		}
+
 		// Check database consistency after every test.
 		mustCheck(db)
 	})
@@ -411,3 +373,22 @@ func trunc(b []byte, length int) []byte {
 	}
 	return b
 }
+
+// writes the current database stats to the testing log.
+func logStats(db *DB) {
+	var stats = db.Stats()
+	fmt.Printf("[db] %-20s %-20s %-20s\n",
+		fmt.Sprintf("pg(%d/%d)", stats.TxStats.PageCount, stats.TxStats.PageAlloc),
+		fmt.Sprintf("cur(%d)", stats.TxStats.CursorCount),
+		fmt.Sprintf("node(%d/%d)", stats.TxStats.NodeCount, stats.TxStats.NodeDeref),
+	)
+	fmt.Printf("     %-20s %-20s %-20s\n",
+		fmt.Sprintf("rebal(%d/%v)", stats.TxStats.Rebalance, truncDuration(stats.TxStats.RebalanceTime)),
+		fmt.Sprintf("spill(%d/%v)", stats.TxStats.Spill, truncDuration(stats.TxStats.SpillTime)),
+		fmt.Sprintf("w(%d/%v)", stats.TxStats.Write, truncDuration(stats.TxStats.WriteTime)),
+	)
+}
+
+func truncDuration(d time.Duration) string {
+	return regexp.MustCompile(`^(\d+)(\.\d+)`).ReplaceAllString(d.String(), "$1")
+}

functional_test.go

@@ -137,7 +137,6 @@ func TestParallelTxs(t *testing.T) {
 			// Wait for readers to finish.
 			wg.Wait()
 		})
-		fmt.Fprint(os.Stderr, ".")
 		return true
 	}, qconfig())
 	assert.NoError(t, err)

node.go

@@ -233,6 +233,9 @@ func (n *node) rebalance() {
 	}
 	n.unbalanced = false
 
+	// Update statistics.
+	n.tx.stats.Rebalance++
+
 	// Ignore if node is above threshold (25%) and has enough keys.
 	var threshold = n.tx.db.pageSize / 4
 	if n.size() > threshold && len(n.inodes) > n.minKeys() {