eth, ethdb: measure database operation latencies too

eth/backend.go

@@ -250,9 +250,9 @@ func New(config *Config) (*Ethereum, error) {
 		return nil, fmt.Errorf("blockchain db err: %v", err)
 	}
 	if db, ok := blockDb.(*ethdb.LDBDatabase); ok {
-		db.GetMeter = metrics.GetOrRegisterMeter("eth/db/block/Gets", metrics.DefaultRegistry)
-		db.PutMeter = metrics.GetOrRegisterMeter("eth/db/block/Puts", metrics.DefaultRegistry)
-		db.DelMeter = metrics.GetOrRegisterMeter("eth/db/block/Dels", metrics.DefaultRegistry)
+		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)
 	}
@@ -261,9 +261,9 @@ func New(config *Config) (*Ethereum, error) {
 		return nil, fmt.Errorf("state db err: %v", err)
 	}
 	if db, ok := stateDb.(*ethdb.LDBDatabase); ok {
-		db.GetMeter = metrics.GetOrRegisterMeter("eth/db/state/Gets", metrics.DefaultRegistry)
-		db.PutMeter = metrics.GetOrRegisterMeter("eth/db/state/Puts", metrics.DefaultRegistry)
-		db.DelMeter = metrics.GetOrRegisterMeter("eth/db/state/Dels", metrics.DefaultRegistry)
+		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)
 	}
@@ -272,9 +272,9 @@ func New(config *Config) (*Ethereum, error) {
 		return nil, fmt.Errorf("extra db err: %v", err)
 	}
 	if db, ok := extraDb.(*ethdb.LDBDatabase); ok {
-		db.GetMeter = metrics.GetOrRegisterMeter("eth/db/extra/Gets", metrics.DefaultRegistry)
-		db.PutMeter = metrics.GetOrRegisterMeter("eth/db/extra/Puts", metrics.DefaultRegistry)
-		db.DelMeter = metrics.GetOrRegisterMeter("eth/db/extra/Dels", metrics.DefaultRegistry)
+		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)
 	}

ethdb/database.go

@@ -1,6 +1,8 @@
 package ethdb
 
 import (
+	"time"
+
 	"github.com/ethereum/go-ethereum/compression/rle"
 	"github.com/ethereum/go-ethereum/logger"
 	"github.com/ethereum/go-ethereum/logger/glog"
@@ -17,9 +19,10 @@ type LDBDatabase struct {
 	fn string      // filename for reporting
 	db *leveldb.DB // LevelDB instance
 
-	GetMeter   metrics.Meter // Meter for measuring the database get request counts
-	PutMeter   metrics.Meter // Meter for measuring the database put request counts
-	DelMeter   metrics.Meter // Meter for measuring the database delete request counts
+	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
 }
@@ -48,10 +51,14 @@ func NewLDBDatabase(file string) (*LDBDatabase, error) {
 
 // Put puts the given key / value to the queue
 func (self *LDBDatabase) Put(key []byte, value []byte) error {
-	dat := rle.Compress(value)
-	if self.PutMeter != nil {
-		self.PutMeter.Mark(1)
+	// Measure the database put latency, if requested
+	if self.PutTimer != nil {
+		start := time.Now()
+		defer self.PutTimer.UpdateSince(start)
 	}
+	// Generate the data to write to disk, update the meter and write
+	dat := rle.Compress(value)
+
 	if self.WriteMeter != nil {
 		self.WriteMeter.Mark(int64(len(dat)))
 	}
@@ -60,13 +67,20 @@ func (self *LDBDatabase) Put(key []byte, value []byte) error {
 
 // Get returns the given key if it's present.
 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)
+	}
+	// Retrieve the key and increment the miss counter if not found
 	dat, err := self.db.Get(key, nil)
 	if err != nil {
+		if self.MissMeter != nil {
+			self.MissMeter.Mark(1)
+		}
 		return nil, err
 	}
-	if self.GetMeter != nil {
-		self.GetMeter.Mark(1)
-	}
+	// Otherwise update the actually retrieved amount of data
 	if self.ReadMeter != nil {
 		self.ReadMeter.Mark(int64(len(dat)))
 	}
@@ -75,9 +89,12 @@ func (self *LDBDatabase) Get(key []byte) ([]byte, error) {
 
 // Delete deletes the key from the queue and database
 func (self *LDBDatabase) Delete(key []byte) error {
-	if self.DelMeter != nil {
-		self.DelMeter.Mark(1)
+	// Measure the database delete latency, if requested
+	if self.DelTimer != nil {
+		start := time.Now()
+		defer self.DelTimer.UpdateSince(start)
 	}
+	// Execute the actual operation
 	return self.db.Delete(key, nil)
 }