From ccbb56b4f2cdba352eaa859ce3e34f999287f5c0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Sat, 27 Jun 2015 20:03:31 +0300 Subject: [PATCH] cmd/geth, eth, ethdb: monitor database compactions --- cmd/geth/monitorcmd.go | 2 +- eth/backend.go | 39 ++++++++++------- ethdb/database.go | 97 ++++++++++++++++++++++++++++++++++++------ 3 files changed, 109 insertions(+), 29 deletions(-) diff --git a/cmd/geth/monitorcmd.go b/cmd/geth/monitorcmd.go index fe771b561..05965f009 100644 --- a/cmd/geth/monitorcmd.go +++ b/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 diff --git a/eth/backend.go b/eth/backend.go index 0da6f128c..21ec71b10 100644 --- a/eth/backend.go +++ b/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") diff --git a/ethdb/database.go b/ethdb/database.go index 8f55d43c3..9ff90d167 100644 --- a/ethdb/database.go +++ b/ethdb/database.go @@ -1,6 +1,8 @@ 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) + } +}