cmd/geth, eth, ethdb: monitor database compactions

cmd/geth/monitorcmd.go

@@ -285,7 +285,7 @@ func updateChart(metric string, data []float64, base *int, chart *termui.LineCha
 	}
 	// Update the chart's label with the scale units
 	units := dataUnits
-	if strings.Contains(metric, "/Percentiles/") || strings.Contains(metric, "/pauses/") {
+	if strings.Contains(metric, "/Percentiles/") || strings.Contains(metric, "/pauses/") || strings.Contains(metric, "/time/") {
 		units = timeUnits
 	}
 	chart.Border.Label = metric

eth/backend.go

@@ -250,33 +250,42 @@ func New(config *Config) (*Ethereum, error) {
 		return nil, fmt.Errorf("blockchain db err: %v", err)
 	}
 	if db, ok := blockDb.(*ethdb.LDBDatabase); ok {
-		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/block/Gets", metrics.DefaultRegistry)
-		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/block/Puts", metrics.DefaultRegistry)
-		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/block/Misses", metrics.DefaultRegistry)
-		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/block/Reads", metrics.DefaultRegistry)
-		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/block/Writes", metrics.DefaultRegistry)
+		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/block/user/gets", metrics.DefaultRegistry)
+		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/block/user/puts", metrics.DefaultRegistry)
+		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/block/user/misses", metrics.DefaultRegistry)
+		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/block/user/reads", metrics.DefaultRegistry)
+		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/block/user/writes", metrics.DefaultRegistry)
+		db.CompTimeMeter = metrics.GetOrRegisterMeter("eth/db/block/compact/time", metrics.DefaultRegistry)
+		db.CompReadMeter = metrics.GetOrRegisterMeter("eth/db/block/compact/input", metrics.DefaultRegistry)
+		db.CompWriteMeter = metrics.GetOrRegisterMeter("eth/db/block/compact/output", metrics.DefaultRegistry)
 	}
 	stateDb, err := newdb(filepath.Join(config.DataDir, "state"))
 	if err != nil {
 		return nil, fmt.Errorf("state db err: %v", err)
 	}
 	if db, ok := stateDb.(*ethdb.LDBDatabase); ok {
-		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/state/Gets", metrics.DefaultRegistry)
-		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/state/Puts", metrics.DefaultRegistry)
-		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/state/Misses", metrics.DefaultRegistry)
-		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/state/Reads", metrics.DefaultRegistry)
-		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/state/Writes", metrics.DefaultRegistry)
+		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/state/user/gets", metrics.DefaultRegistry)
+		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/state/user/puts", metrics.DefaultRegistry)
+		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/state/user/misses", metrics.DefaultRegistry)
+		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/state/user/reads", metrics.DefaultRegistry)
+		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/state/user/writes", metrics.DefaultRegistry)
+		db.CompTimeMeter = metrics.GetOrRegisterMeter("eth/db/state/compact/time", metrics.DefaultRegistry)
+		db.CompReadMeter = metrics.GetOrRegisterMeter("eth/db/state/compact/input", metrics.DefaultRegistry)
+		db.CompWriteMeter = metrics.GetOrRegisterMeter("eth/db/state/compact/output", metrics.DefaultRegistry)
 	}
 	extraDb, err := newdb(filepath.Join(config.DataDir, "extra"))
 	if err != nil {
 		return nil, fmt.Errorf("extra db err: %v", err)
 	}
 	if db, ok := extraDb.(*ethdb.LDBDatabase); ok {
-		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/extra/Gets", metrics.DefaultRegistry)
-		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/extra/Puts", metrics.DefaultRegistry)
-		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/extra/Misses", metrics.DefaultRegistry)
-		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/extra/Reads", metrics.DefaultRegistry)
-		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/extra/Writes", metrics.DefaultRegistry)
+		db.GetTimer = metrics.GetOrRegisterTimer("eth/db/extra/user/gets", metrics.DefaultRegistry)
+		db.PutTimer = metrics.GetOrRegisterTimer("eth/db/extra/user/puts", metrics.DefaultRegistry)
+		db.MissMeter = metrics.GetOrRegisterMeter("eth/db/extra/user/misses", metrics.DefaultRegistry)
+		db.ReadMeter = metrics.GetOrRegisterMeter("eth/db/extra/user/reads", metrics.DefaultRegistry)
+		db.WriteMeter = metrics.GetOrRegisterMeter("eth/db/extra/user/writes", metrics.DefaultRegistry)
+		db.CompTimeMeter = metrics.GetOrRegisterMeter("eth/db/extra/compact/time", metrics.DefaultRegistry)
+		db.CompReadMeter = metrics.GetOrRegisterMeter("eth/db/extra/compact/input", metrics.DefaultRegistry)
+		db.CompWriteMeter = metrics.GetOrRegisterMeter("eth/db/extra/compact/output", metrics.DefaultRegistry)
 	}
 	nodeDb := filepath.Join(config.DataDir, "nodes")
 

ethdb/database.go

 package ethdb
 
 import (
+	"strconv"
+	"strings"
 	"time"
 
 	"github.com/ethereum/go-ethereum/compression/rle"
@@ -19,12 +21,15 @@ type LDBDatabase struct {
 	fn string      // filename for reporting
 	db *leveldb.DB // LevelDB instance
 
-	GetTimer   metrics.Timer // Timer for measuring the database get request counts and latencies
-	PutTimer   metrics.Timer // Timer for measuring the database put request counts and latencies
-	DelTimer   metrics.Timer // Timer for measuring the database delete request counts and latencies
-	MissMeter  metrics.Meter // MEter for measuring the missed database get requests
-	ReadMeter  metrics.Meter // Meter for measuring the database get request data usage
-	WriteMeter metrics.Meter // Meter for measuring the database put request data usage
+	GetTimer       metrics.Timer // Timer for measuring the database get request counts and latencies
+	PutTimer       metrics.Timer // Timer for measuring the database put request counts and latencies
+	DelTimer       metrics.Timer // Timer for measuring the database delete request counts and latencies
+	MissMeter      metrics.Meter // Meter for measuring the missed database get requests
+	ReadMeter      metrics.Meter // Meter for measuring the database get request data usage
+	WriteMeter     metrics.Meter // Meter for measuring the database put request data usage
+	CompTimeMeter  metrics.Meter // Meter for measuring the total time spent in database compaction
+	CompReadMeter  metrics.Meter // Meter for measuring the data read during compaction
+	CompWriteMeter metrics.Meter // Meter for measuring the data written during compaction
 }
 
 // NewLDBDatabase returns a LevelDB wrapped object. LDBDatabase does not persist data by
@@ -45,6 +50,7 @@ func NewLDBDatabase(file string) (*LDBDatabase, error) {
 		fn: file,
 		db: db,
 	}
+	go database.meter(3 * time.Second)
 
 	return database, nil
 }
@@ -53,8 +59,7 @@ func NewLDBDatabase(file string) (*LDBDatabase, error) {
 func (self *LDBDatabase) Put(key []byte, value []byte) error {
 	// Measure the database put latency, if requested
 	if self.PutTimer != nil {
-		start := time.Now()
-		defer self.PutTimer.UpdateSince(start)
+		defer self.PutTimer.UpdateSince(time.Now())
 	}
 	// Generate the data to write to disk, update the meter and write
 	dat := rle.Compress(value)
@@ -69,8 +74,7 @@ func (self *LDBDatabase) Put(key []byte, value []byte) error {
 func (self *LDBDatabase) Get(key []byte) ([]byte, error) {
 	// Measure the database get latency, if requested
 	if self.GetTimer != nil {
-		start := time.Now()
-		defer self.GetTimer.UpdateSince(start)
+		defer self.GetTimer.UpdateSince(time.Now())
 	}
 	// Retrieve the key and increment the miss counter if not found
 	dat, err := self.db.Get(key, nil)
@@ -91,8 +95,7 @@ func (self *LDBDatabase) Get(key []byte) ([]byte, error) {
 func (self *LDBDatabase) Delete(key []byte) error {
 	// Measure the database delete latency, if requested
 	if self.DelTimer != nil {
-		start := time.Now()
-		defer self.DelTimer.UpdateSince(start)
+		defer self.DelTimer.UpdateSince(time.Now())
 	}
 	// Execute the actual operation
 	return self.db.Delete(key, nil)
@@ -111,7 +114,6 @@ func (self *LDBDatabase) Close() {
 	if err := self.Flush(); err != nil {
 		glog.V(logger.Error).Infof("error: flush '%s': %v\n", self.fn, err)
 	}
-
 	self.db.Close()
 	glog.V(logger.Error).Infoln("flushed and closed db:", self.fn)
 }
@@ -119,3 +121,72 @@ func (self *LDBDatabase) Close() {
 func (self *LDBDatabase) LDB() *leveldb.DB {
 	return self.db
 }
+
+// meter periodically retrieves internal leveldb counters and reports them to
+// the metrics subsystem.
+//
+// This is how a stats table look like (currently):
+//   Compactions
+//    Level |   Tables   |    Size(MB)   |    Time(sec)  |    Read(MB)   |   Write(MB)
+//   -------+------------+---------------+---------------+---------------+---------------
+//      0   |          0 |       0.00000 |       1.27969 |       0.00000 |      12.31098
+//      1   |         85 |     109.27913 |      28.09293 |     213.92493 |     214.26294
+//      2   |        523 |    1000.37159 |       7.26059 |      66.86342 |      66.77884
+//      3   |        570 |    1113.18458 |       0.00000 |       0.00000 |       0.00000
+func (self *LDBDatabase) meter(refresh time.Duration) {
+	// Create the counters to store current and previous values
+	counters := make([][]float64, 2)
+	for i := 0; i < 2; i++ {
+		counters[i] = make([]float64, 3)
+	}
+	// Iterate ad infinitum and collect the stats
+	for i := 1; ; i++ {
+		// Retrieve the database stats
+		stats, err := self.db.GetProperty("leveldb.stats")
+		if err != nil {
+			glog.V(logger.Error).Infof("failed to read database stats: %v", err)
+			return
+		}
+		// Find the compaction table, skip the header
+		lines := strings.Split(stats, "\n")
+		for len(lines) > 0 && strings.TrimSpace(lines[0]) != "Compactions" {
+			lines = lines[1:]
+		}
+		if len(lines) <= 3 {
+			glog.V(logger.Error).Infof("compaction table not found")
+			return
+		}
+		lines = lines[3:]
+
+		// Iterate over all the table rows, and accumulate the entries
+		for j := 0; j < len(counters[i%2]); j++ {
+			counters[i%2][j] = 0
+		}
+		for _, line := range lines {
+			parts := strings.Split(line, "|")
+			if len(parts) != 6 {
+				break
+			}
+			for idx, counter := range parts[3:] {
+				if value, err := strconv.ParseFloat(strings.TrimSpace(counter), 64); err != nil {
+					glog.V(logger.Error).Infof("compaction entry parsing failed: %v", err)
+					return
+				} else {
+					counters[i%2][idx] += value
+				}
+			}
+		}
+		// Update all the requested meters
+		if self.CompTimeMeter != nil {
+			self.CompTimeMeter.Mark(int64((counters[i%2][0] - counters[(i-1)%2][0]) * 1000 * 1000 * 1000))
+		}
+		if self.CompReadMeter != nil {
+			self.CompReadMeter.Mark(int64((counters[i%2][1] - counters[(i-1)%2][1]) * 1024 * 1024))
+		}
+		if self.CompWriteMeter != nil {
+			self.CompWriteMeter.Mark(int64((counters[i%2][2] - counters[(i-1)%2][2]) * 1024 * 1024))
+		}
+		// Sleep a bit, then repeat the stats collection
+		time.Sleep(refresh)
+	}
+}