Add performance counters.

This commit adds performance counters for each transaction which are rolled
up to the database level on each commit/rollback. Counters are meant to be
a very fast way to track what is going on in the database. A few timers are
also added in areas where the time.Now() overhead is not noticible.

The DB.Stat() function is now deprecated since the `bolt` CLI now performs
similar functions.

Fixes #108.

1 files changed, 30 insertions, 49 deletions

diff --git a/db_test.go b/db_test.go
index 0593759..df1aad3 100644
--- a/db_test.go
+++ b/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")
+}