From a30dc0ce7ce6a8e74d9d5b489f38064a2f7efaed Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Wed, 13 Dec 2017 10:32:17 +0800 Subject: [PATCH 1/7] vendor: update leveldb --- vendor/github.com/syndtr/goleveldb/leveldb/db.go | 4 ++-- .../syndtr/goleveldb/leveldb/iterator/iter.go | 2 +- .../syndtr/goleveldb/leveldb/memdb/memdb.go | 2 +- .../syndtr/goleveldb/leveldb/opt/options.go | 13 +++++++++++++ .../syndtr/goleveldb/leveldb/util/util.go | 2 +- vendor/vendor.json | 6 +++--- 6 files changed, 21 insertions(+), 8 deletions(-) diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/db.go b/vendor/github.com/syndtr/goleveldb/leveldb/db.go index b0cdcb3d0a..fc3c408f8d 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/db.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/db.go @@ -321,7 +321,7 @@ func recoverTable(s *session, o *opt.Options) error { } } err = iter.Error() - if err != nil { + if err != nil && !errors.IsCorrupted(err) { return } err = tw.Close() @@ -392,7 +392,7 @@ func recoverTable(s *session, o *opt.Options) error { } imax = append(imax[:0], key...) } - if err := iter.Error(); err != nil { + if err := iter.Error(); err != nil && !errors.IsCorrupted(err) { iter.Release() return err } diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/iterator/iter.go b/vendor/github.com/syndtr/goleveldb/leveldb/iterator/iter.go index 3b55532746..b16e3a7045 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/iterator/iter.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/iterator/iter.go @@ -88,7 +88,7 @@ type Iterator interface { // its contents may change on the next call to any 'seeks method'. Key() []byte - // Value returns the key of the current key/value pair, or nil if done. + // Value returns the value of the current key/value pair, or nil if done. // The caller should not modify the contents of the returned slice, and // its contents may change on the next call to any 'seeks method'. Value() []byte diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/memdb/memdb.go b/vendor/github.com/syndtr/goleveldb/leveldb/memdb/memdb.go index 18a19ed424..b661c08a93 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/memdb/memdb.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/memdb/memdb.go @@ -329,7 +329,7 @@ func (p *DB) Delete(key []byte) error { h := p.nodeData[node+nHeight] for i, n := range p.prevNode[:h] { - m := n + 4 + i + m := n + nNext + i p.nodeData[m] = p.nodeData[p.nodeData[m]+nNext+i] } diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go b/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go index 44e7d9adce..f2461d87b1 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go @@ -41,6 +41,7 @@ var ( DefaultWriteBuffer = 4 * MiB DefaultWriteL0PauseTrigger = 12 DefaultWriteL0SlowdownTrigger = 8 + DefaultSuspendedWriteStatSize = 100 ) // Cacher is a caching algorithm. @@ -357,6 +358,11 @@ type Options struct { // // The default value is 8. WriteL0SlowdownTrigger int + + // SuspendedWriteStatSize defines the upper limit of the cached suspended write operation statistics. + // + // The default value is 100. + SuspendedWriteStatSize int } func (o *Options) GetAltFilters() []filter.Filter { @@ -609,6 +615,13 @@ func (o *Options) GetWriteL0SlowdownTrigger() int { return o.WriteL0SlowdownTrigger } +func (o *Options) GetSuspendedWriteStatSize() int { + if o == nil || o.SuspendedWriteStatSize == 0 { + return DefaultSuspendedWriteStatSize + } + return o.SuspendedWriteStatSize +} + // ReadOptions holds the optional parameters for 'read operation'. The // 'read operation' includes Get, Find and NewIterator. type ReadOptions struct { diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/util/util.go b/vendor/github.com/syndtr/goleveldb/leveldb/util/util.go index f35976865b..80614afc58 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/util/util.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/util/util.go @@ -19,7 +19,7 @@ var ( // Releaser is the interface that wraps the basic Release method. type Releaser interface { // Release releases associated resources. Release should always success - // and can be called multipe times without causing error. + // and can be called multiple times without causing error. Release() } diff --git a/vendor/vendor.json b/vendor/vendor.json index 26cc188ce2..b3128a5c62 100644 --- a/vendor/vendor.json +++ b/vendor/vendor.json @@ -358,10 +358,10 @@ "revisionTime": "2017-07-05T02:17:15Z" }, { - "checksumSHA1": "yHbyLpI/Meh0DGrmi8x6FrDxxUY=", + "checksumSHA1": "spMeORRgS1azN91KYqJgoxBmhMw=", "path": "github.com/syndtr/goleveldb/leveldb", - "revision": "b89cc31ef7977104127d34c1bd31ebd1a9db2199", - "revisionTime": "2017-07-25T06:48:36Z" + "revision": "3d8f4155ffd9029d32e5cf03853b58759b6e3710", + "revisionTime": "2017-12-09T15:37:43Z" }, { "checksumSHA1": "EKIow7XkgNdWvR/982ffIZxKG8Y=", From 61920f66003b574060cf3f21bbbf1856b4eb86b6 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Wed, 13 Dec 2017 14:01:03 +0800 Subject: [PATCH 2/7] ethdb: add write delay meters --- ethdb/database.go | 43 +++++++++++++++++++++++++++++++++---------- 1 file changed, 33 insertions(+), 10 deletions(-) diff --git a/ethdb/database.go b/ethdb/database.go index 93755dd7e3..57a693359e 100644 --- a/ethdb/database.go +++ b/ethdb/database.go @@ -30,6 +30,7 @@ import ( "github.com/syndtr/goleveldb/leveldb/iterator" "github.com/syndtr/goleveldb/leveldb/opt" + "fmt" gometrics "github.com/rcrowley/go-metrics" ) @@ -39,15 +40,17 @@ type LDBDatabase struct { fn string // filename for reporting db *leveldb.DB // LevelDB instance - getTimer gometrics.Timer // Timer for measuring the database get request counts and latencies - putTimer gometrics.Timer // Timer for measuring the database put request counts and latencies - delTimer gometrics.Timer // Timer for measuring the database delete request counts and latencies - missMeter gometrics.Meter // Meter for measuring the missed database get requests - readMeter gometrics.Meter // Meter for measuring the database get request data usage - writeMeter gometrics.Meter // Meter for measuring the database put request data usage - compTimeMeter gometrics.Meter // Meter for measuring the total time spent in database compaction - compReadMeter gometrics.Meter // Meter for measuring the data read during compaction - compWriteMeter gometrics.Meter // Meter for measuring the data written during compaction + getTimer gometrics.Timer // Timer for measuring the database get request counts and latencies + putTimer gometrics.Timer // Timer for measuring the database put request counts and latencies + delTimer gometrics.Timer // Timer for measuring the database delete request counts and latencies + writeDelayTimer gometrics.Timer // Timer for measuring the write delay duration due to database compaction + missMeter gometrics.Meter // Meter for measuring the missed database get requests + readMeter gometrics.Meter // Meter for measuring the database get request data usage + writeMeter gometrics.Meter // Meter for measuring the database put request data usage + writeDelayMeter gometrics.Meter // Meter for measuring the write delay number due to database compaction + compTimeMeter gometrics.Meter // Meter for measuring the total time spent in database compaction + compReadMeter gometrics.Meter // Meter for measuring the data read during compaction + compWriteMeter gometrics.Meter // Meter for measuring the data written during compaction quitLock sync.Mutex // Mutex protecting the quit channel access quitChan chan chan error // Quit channel to stop the metrics collection before closing the database @@ -186,6 +189,9 @@ func (db *LDBDatabase) Meter(prefix string) { db.missMeter = metrics.NewMeter(prefix + "user/misses") db.readMeter = metrics.NewMeter(prefix + "user/reads") db.writeMeter = metrics.NewMeter(prefix + "user/writes") + + db.writeDelayTimer = metrics.NewTimer(prefix + "compact/writedelay/duration") + db.writeDelayMeter = metrics.NewMeter(prefix + "compact/writedelay/counter") db.compTimeMeter = metrics.NewMeter(prefix + "compact/time") db.compReadMeter = metrics.NewMeter(prefix + "compact/input") db.compWriteMeter = metrics.NewMeter(prefix + "compact/output") @@ -213,7 +219,7 @@ func (db *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) + counters[i] = make([]float64, 5) } // Iterate ad infinitum and collect the stats for i := 1; ; i++ { @@ -262,6 +268,23 @@ func (db *LDBDatabase) meter(refresh time.Duration) { if db.compWriteMeter != nil { db.compWriteMeter.Mark(int64((counters[i%2][2] - counters[(i-1)%2][2]) * 1024 * 1024)) } + + // Stat write delay. + writeDelay, err := db.db.GetProperty("leveldb.writedelay") + if err != nil { + db.log.Error("Failed to read database write delay statistic", "err", err) + return + } + if n, err := fmt.Sscanf(writeDelay, "DelayN: %f Delay(sec):%.5f", &counters[i%2][3], &counters[i%2][4]); n != 2 || err != nil { + db.log.Error("Write delay statistic not found") + return + } + if db.writeDelayTimer != nil { + db.writeDelayTimer.Update(time.Duration(int64((counters[i%2][4] - counters[(i-1)%2][4]) * 1000 * 1000 * 1000))) + } + if db.writeDelayMeter != nil { + db.writeDelayMeter.Mark(int64((counters[i%2][3] - counters[(i-1)%2][3]))) + } // Sleep a bit, then repeat the stats collection select { case errc := <-db.quitChan: From 8978fcb4ac5d6d272815e307d586760b4ca1965a Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Wed, 13 Dec 2017 14:33:37 +0800 Subject: [PATCH 3/7] vendor: revert leveldb modifications --- .../syndtr/goleveldb/leveldb/opt/options.go | 13 ------------- 1 file changed, 13 deletions(-) diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go b/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go index f2461d87b1..44e7d9adce 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/opt/options.go @@ -41,7 +41,6 @@ var ( DefaultWriteBuffer = 4 * MiB DefaultWriteL0PauseTrigger = 12 DefaultWriteL0SlowdownTrigger = 8 - DefaultSuspendedWriteStatSize = 100 ) // Cacher is a caching algorithm. @@ -358,11 +357,6 @@ type Options struct { // // The default value is 8. WriteL0SlowdownTrigger int - - // SuspendedWriteStatSize defines the upper limit of the cached suspended write operation statistics. - // - // The default value is 100. - SuspendedWriteStatSize int } func (o *Options) GetAltFilters() []filter.Filter { @@ -615,13 +609,6 @@ func (o *Options) GetWriteL0SlowdownTrigger() int { return o.WriteL0SlowdownTrigger } -func (o *Options) GetSuspendedWriteStatSize() int { - if o == nil || o.SuspendedWriteStatSize == 0 { - return DefaultSuspendedWriteStatSize - } - return o.SuspendedWriteStatSize -} - // ReadOptions holds the optional parameters for 'read operation'. The // 'read operation' includes Get, Find and NewIterator. type ReadOptions struct { From 4b5757c36c1b094ccec70aa9089412ace34e59f9 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Thu, 14 Dec 2017 22:46:40 +0800 Subject: [PATCH 4/7] vendor: update leveldb --- vendor/github.com/syndtr/goleveldb/leveldb/db.go | 13 ++++++++++--- .../github.com/syndtr/goleveldb/leveldb/db_write.go | 3 +++ vendor/vendor.json | 6 +++--- 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/db.go b/vendor/github.com/syndtr/goleveldb/leveldb/db.go index fc3c408f8d..ea5595eb3a 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/db.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/db.go @@ -32,6 +32,11 @@ type DB struct { // Need 64-bit alignment. seq uint64 + // Stats. Need 64-bit alignment. + cWriteDelay int64 // The cumulative duration of write delays + cWriteDelayN int32 // The cumulative number of write delays + aliveSnaps, aliveIters int32 + // Session. s *session @@ -49,9 +54,6 @@ type DB struct { snapsMu sync.Mutex snapsList *list.List - // Stats. - aliveSnaps, aliveIters int32 - // Write. batchPool sync.Pool writeMergeC chan writeMerge @@ -904,6 +906,8 @@ func (db *DB) GetSnapshot() (*Snapshot, error) { // Returns the number of files at level 'n'. // leveldb.stats // Returns statistics of the underlying DB. +// leveldb.writedelay +// Returns cumulative write delay caused by compaction. // leveldb.sstables // Returns sstables list for each level. // leveldb.blockpool @@ -955,6 +959,9 @@ func (db *DB) GetProperty(name string) (value string, err error) { level, len(tables), float64(tables.size())/1048576.0, duration.Seconds(), float64(read)/1048576.0, float64(write)/1048576.0) } + case p == "writedelay": + writeDelayN, writeDelay := atomic.LoadInt32(&db.cWriteDelayN), time.Duration(atomic.LoadInt64(&db.cWriteDelay)) + value = fmt.Sprintf("DelayN:%d Delay:%s", writeDelayN, writeDelay) case p == "sstables": for level, tables := range v.levels { value += fmt.Sprintf("--- level %d ---\n", level) diff --git a/vendor/github.com/syndtr/goleveldb/leveldb/db_write.go b/vendor/github.com/syndtr/goleveldb/leveldb/db_write.go index 5b6cb487dc..3662d95f07 100644 --- a/vendor/github.com/syndtr/goleveldb/leveldb/db_write.go +++ b/vendor/github.com/syndtr/goleveldb/leveldb/db_write.go @@ -7,6 +7,7 @@ package leveldb import ( + "sync/atomic" "time" "github.com/syndtr/goleveldb/leveldb/memdb" @@ -117,6 +118,8 @@ func (db *DB) flush(n int) (mdb *memDB, mdbFree int, err error) { db.writeDelayN++ } else if db.writeDelayN > 0 { db.logf("db@write was delayed N·%d T·%v", db.writeDelayN, db.writeDelay) + atomic.AddInt32(&db.cWriteDelayN, int32(db.writeDelayN)) + atomic.AddInt64(&db.cWriteDelay, int64(db.writeDelay)) db.writeDelay = 0 db.writeDelayN = 0 } diff --git a/vendor/vendor.json b/vendor/vendor.json index b3128a5c62..f69ada5535 100644 --- a/vendor/vendor.json +++ b/vendor/vendor.json @@ -358,10 +358,10 @@ "revisionTime": "2017-07-05T02:17:15Z" }, { - "checksumSHA1": "spMeORRgS1azN91KYqJgoxBmhMw=", + "checksumSHA1": "l9hsW4atYllqlNjJUwHb6lyLn+I=", "path": "github.com/syndtr/goleveldb/leveldb", - "revision": "3d8f4155ffd9029d32e5cf03853b58759b6e3710", - "revisionTime": "2017-12-09T15:37:43Z" + "revision": "34011bf325bce385408353a30b101fe5e923eb6e", + "revisionTime": "2017-12-14T12:08:11Z" }, { "checksumSHA1": "EKIow7XkgNdWvR/982ffIZxKG8Y=", From 522e0d44249edf8bd88fa04bf02c46c546abe656 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Fri, 15 Dec 2017 10:59:48 +0800 Subject: [PATCH 5/7] ethdb: update write delay statistic --- ethdb/database.go | 48 ++++++++++++++++++++++++++++++----------------- 1 file changed, 31 insertions(+), 17 deletions(-) diff --git a/ethdb/database.go b/ethdb/database.go index 57a693359e..d438b41471 100644 --- a/ethdb/database.go +++ b/ethdb/database.go @@ -40,17 +40,17 @@ type LDBDatabase struct { fn string // filename for reporting db *leveldb.DB // LevelDB instance - getTimer gometrics.Timer // Timer for measuring the database get request counts and latencies - putTimer gometrics.Timer // Timer for measuring the database put request counts and latencies - delTimer gometrics.Timer // Timer for measuring the database delete request counts and latencies - writeDelayTimer gometrics.Timer // Timer for measuring the write delay duration due to database compaction - missMeter gometrics.Meter // Meter for measuring the missed database get requests - readMeter gometrics.Meter // Meter for measuring the database get request data usage - writeMeter gometrics.Meter // Meter for measuring the database put request data usage - writeDelayMeter gometrics.Meter // Meter for measuring the write delay number due to database compaction - compTimeMeter gometrics.Meter // Meter for measuring the total time spent in database compaction - compReadMeter gometrics.Meter // Meter for measuring the data read during compaction - compWriteMeter gometrics.Meter // Meter for measuring the data written during compaction + getTimer gometrics.Timer // Timer for measuring the database get request counts and latencies + putTimer gometrics.Timer // Timer for measuring the database put request counts and latencies + delTimer gometrics.Timer // Timer for measuring the database delete request counts and latencies + missMeter gometrics.Meter // Meter for measuring the missed database get requests + readMeter gometrics.Meter // Meter for measuring the database get request data usage + writeMeter gometrics.Meter // Meter for measuring the database put request data usage + writeDelayNMeter gometrics.Meter // Meter for measuring the write delay number due to database compaction + writeDelayMeter gometrics.Meter // Meter for measuring the write delay duration due to database compaction + compTimeMeter gometrics.Meter // Meter for measuring the total time spent in database compaction + compReadMeter gometrics.Meter // Meter for measuring the data read during compaction + compWriteMeter gometrics.Meter // Meter for measuring the data written during compaction quitLock sync.Mutex // Mutex protecting the quit channel access quitChan chan chan error // Quit channel to stop the metrics collection before closing the database @@ -190,8 +190,8 @@ func (db *LDBDatabase) Meter(prefix string) { db.readMeter = metrics.NewMeter(prefix + "user/reads") db.writeMeter = metrics.NewMeter(prefix + "user/writes") - db.writeDelayTimer = metrics.NewTimer(prefix + "compact/writedelay/duration") - db.writeDelayMeter = metrics.NewMeter(prefix + "compact/writedelay/counter") + db.writeDelayMeter = metrics.NewMeter(prefix + "compact/writedelay/duration") + db.writeDelayNMeter = metrics.NewMeter(prefix + "compact/writedelay/counter") db.compTimeMeter = metrics.NewMeter(prefix + "compact/time") db.compReadMeter = metrics.NewMeter(prefix + "compact/input") db.compWriteMeter = metrics.NewMeter(prefix + "compact/output") @@ -275,15 +275,29 @@ func (db *LDBDatabase) meter(refresh time.Duration) { db.log.Error("Failed to read database write delay statistic", "err", err) return } - if n, err := fmt.Sscanf(writeDelay, "DelayN: %f Delay(sec):%.5f", &counters[i%2][3], &counters[i%2][4]); n != 2 || err != nil { + var ( + delayN int32 + delayDuration string + duration time.Duration + ) + if n, err := fmt.Sscanf(writeDelay, "DelayN:%d Delay:%s", &delayN, &delayDuration); n != 2 || err != nil { db.log.Error("Write delay statistic not found") return } - if db.writeDelayTimer != nil { - db.writeDelayTimer.Update(time.Duration(int64((counters[i%2][4] - counters[(i-1)%2][4]) * 1000 * 1000 * 1000))) + duration, err = time.ParseDuration(delayDuration) + if err != nil { + db.log.Error("Failed to parse delay duration", "err", err) + return } + + counters[i%2][3], counters[i%2][4] = float64(delayN), float64(duration.Nanoseconds()) + + if db.writeDelayNMeter != nil { + db.writeDelayNMeter.Mark(int64((counters[i%2][3] - counters[(i-1)%2][3]))) + } + if db.writeDelayMeter != nil { - db.writeDelayMeter.Mark(int64((counters[i%2][3] - counters[(i-1)%2][3]))) + db.writeDelayMeter.Mark(int64((counters[i%2][4] - counters[(i-1)%2][4]))) } // Sleep a bit, then repeat the stats collection select { From c3bb251d337bcd4f774ab030337c29b103339ba3 Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Tue, 19 Dec 2017 16:02:28 +0800 Subject: [PATCH 6/7] ethdb: print a warning log if write delay exceeds threshold --- ethdb/database.go | 130 ++++++++++++++++++++++++++-------------------- 1 file changed, 73 insertions(+), 57 deletions(-) diff --git a/ethdb/database.go b/ethdb/database.go index d438b41471..592ce15d8d 100644 --- a/ethdb/database.go +++ b/ethdb/database.go @@ -34,7 +34,10 @@ import ( gometrics "github.com/rcrowley/go-metrics" ) -var OpenFileLimit = 64 +const ( + writeDelayNThreshold = 250 + writeDelayThreshold = 500 * time.Millisecond +) type LDBDatabase struct { fn string // filename for reporting @@ -178,23 +181,23 @@ func (db *LDBDatabase) LDB() *leveldb.DB { // Meter configures the database metrics collectors and func (db *LDBDatabase) Meter(prefix string) { - // Short circuit metering if the metrics system is disabled - if !metrics.Enabled { - return - } - // Initialize all the metrics collector at the requested prefix - db.getTimer = metrics.NewTimer(prefix + "user/gets") - db.putTimer = metrics.NewTimer(prefix + "user/puts") - db.delTimer = metrics.NewTimer(prefix + "user/dels") - db.missMeter = metrics.NewMeter(prefix + "user/misses") - db.readMeter = metrics.NewMeter(prefix + "user/reads") - db.writeMeter = metrics.NewMeter(prefix + "user/writes") + if metrics.Enabled { + // Initialize all database related metrics collector at the requested prefix + // if metric is enable. + db.getTimer = metrics.NewTimer(prefix + "user/gets") + db.putTimer = metrics.NewTimer(prefix + "user/puts") + db.delTimer = metrics.NewTimer(prefix + "user/dels") + db.missMeter = metrics.NewMeter(prefix + "user/misses") + db.readMeter = metrics.NewMeter(prefix + "user/reads") + db.writeMeter = metrics.NewMeter(prefix + "user/writes") + db.compTimeMeter = metrics.NewMeter(prefix + "compact/time") + db.compReadMeter = metrics.NewMeter(prefix + "compact/input") + db.compWriteMeter = metrics.NewMeter(prefix + "compact/output") + } + // Initialize essential write delay metrics no matter metric is enable or not. db.writeDelayMeter = metrics.NewMeter(prefix + "compact/writedelay/duration") db.writeDelayNMeter = metrics.NewMeter(prefix + "compact/writedelay/counter") - db.compTimeMeter = metrics.NewMeter(prefix + "compact/time") - db.compReadMeter = metrics.NewMeter(prefix + "compact/input") - db.compWriteMeter = metrics.NewMeter(prefix + "compact/output") // Create a quit channel for the periodic collector and run it db.quitLock.Lock() @@ -223,53 +226,55 @@ func (db *LDBDatabase) meter(refresh time.Duration) { } // Iterate ad infinitum and collect the stats for i := 1; ; i++ { - // Retrieve the database stats - stats, err := db.db.GetProperty("leveldb.stats") - if err != nil { - db.log.Error("Failed to read database stats", "err", 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 { - db.log.Error("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 + if metrics.Enabled { + // Retrieve the database stats + stats, err := db.db.GetProperty("leveldb.stats") + if err != nil { + db.log.Error("Failed to read database stats", "err", err) + return } - for idx, counter := range parts[3:] { - value, err := strconv.ParseFloat(strings.TrimSpace(counter), 64) - if err != nil { - db.log.Error("Compaction entry parsing failed", "err", 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 { + db.log.Error("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 } - counters[i%2][idx] += value + for idx, counter := range parts[3:] { + value, err := strconv.ParseFloat(strings.TrimSpace(counter), 64) + if err != nil { + db.log.Error("Compaction entry parsing failed", "err", err) + return + } + counters[i%2][idx] += value + } + } + // Update all the requested meters + if db.compTimeMeter != nil { + db.compTimeMeter.Mark(int64((counters[i%2][0] - counters[(i-1)%2][0]) * 1000 * 1000 * 1000)) + } + if db.compReadMeter != nil { + db.compReadMeter.Mark(int64((counters[i%2][1] - counters[(i-1)%2][1]) * 1024 * 1024)) + } + if db.compWriteMeter != nil { + db.compWriteMeter.Mark(int64((counters[i%2][2] - counters[(i-1)%2][2]) * 1024 * 1024)) } } - // Update all the requested meters - if db.compTimeMeter != nil { - db.compTimeMeter.Mark(int64((counters[i%2][0] - counters[(i-1)%2][0]) * 1000 * 1000 * 1000)) - } - if db.compReadMeter != nil { - db.compReadMeter.Mark(int64((counters[i%2][1] - counters[(i-1)%2][1]) * 1024 * 1024)) - } - if db.compWriteMeter != nil { - db.compWriteMeter.Mark(int64((counters[i%2][2] - counters[(i-1)%2][2]) * 1024 * 1024)) - } - // Stat write delay. + // Gather write delay statistic writeDelay, err := db.db.GetProperty("leveldb.writedelay") if err != nil { db.log.Error("Failed to read database write delay statistic", "err", err) @@ -294,11 +299,22 @@ func (db *LDBDatabase) meter(refresh time.Duration) { if db.writeDelayNMeter != nil { db.writeDelayNMeter.Mark(int64((counters[i%2][3] - counters[(i-1)%2][3]))) + // If the write delay number been collected in the last minute exceeds the predefined threshold, + // print a warning log here. + if int(db.writeDelayNMeter.Rate1()) > writeDelayNThreshold { + db.log.Warn("Write delay number exceeds the threshold (250) in the last minute") + } } if db.writeDelayMeter != nil { db.writeDelayMeter.Mark(int64((counters[i%2][4] - counters[(i-1)%2][4]))) + // If the write delay duration been collected in the last minute exceeds the predefined threshold, + // print a warning log here. + if int64(db.writeDelayMeter.Rate1()) > writeDelayThreshold.Nanoseconds() { + db.log.Warn("Write delay duration exceeds the threshold (0.5sec) in the last minute") + } } + // Sleep a bit, then repeat the stats collection select { case errc := <-db.quitChan: From f2d8d85fd7ec67b8ade252c76e093715c1b5b12f Mon Sep 17 00:00:00 2001 From: rjl493456442 Date: Sun, 24 Dec 2017 13:39:19 +0800 Subject: [PATCH 7/7] ethdb: change write delay threshold and redisplay throttler --- ethdb/database.go | 25 +++++++++++++++++++------ 1 file changed, 19 insertions(+), 6 deletions(-) diff --git a/ethdb/database.go b/ethdb/database.go index 592ce15d8d..868875f966 100644 --- a/ethdb/database.go +++ b/ethdb/database.go @@ -35,8 +35,9 @@ import ( ) const ( - writeDelayNThreshold = 250 - writeDelayThreshold = 500 * time.Millisecond + writeDelayNThreshold = 200 + writeDelayThreshold = 350 * time.Millisecond + writeDelayWarningThrottler = 1 * time.Minute ) type LDBDatabase struct { @@ -219,6 +220,10 @@ func (db *LDBDatabase) Meter(prefix string) { // 2 | 523 | 1000.37159 | 7.26059 | 66.86342 | 66.77884 // 3 | 570 | 1113.18458 | 0.00000 | 0.00000 | 0.00000 func (db *LDBDatabase) meter(refresh time.Duration) { + var ( + lastWriteDelay time.Time + lastWriteDelayN time.Time + ) // Create the counters to store current and previous values counters := make([][]float64, 2) for i := 0; i < 2; i++ { @@ -301,8 +306,12 @@ func (db *LDBDatabase) meter(refresh time.Duration) { db.writeDelayNMeter.Mark(int64((counters[i%2][3] - counters[(i-1)%2][3]))) // If the write delay number been collected in the last minute exceeds the predefined threshold, // print a warning log here. - if int(db.writeDelayNMeter.Rate1()) > writeDelayNThreshold { - db.log.Warn("Write delay number exceeds the threshold (250) in the last minute") + // If a warning that db performance is laggy has been displayed, + // any subsequent warnings will be withhold for 1 minute to don't overwhelm the user. + if int(db.writeDelayNMeter.Rate1()) > writeDelayNThreshold && + time.Now().After(lastWriteDelayN.Add(writeDelayWarningThrottler)) { + db.log.Warn("Write delay number exceeds the threshold (200) in the last minute") + lastWriteDelayN = time.Now() } } @@ -310,8 +319,12 @@ func (db *LDBDatabase) meter(refresh time.Duration) { db.writeDelayMeter.Mark(int64((counters[i%2][4] - counters[(i-1)%2][4]))) // If the write delay duration been collected in the last minute exceeds the predefined threshold, // print a warning log here. - if int64(db.writeDelayMeter.Rate1()) > writeDelayThreshold.Nanoseconds() { - db.log.Warn("Write delay duration exceeds the threshold (0.5sec) in the last minute") + // If a warning that db performance is laggy has been displayed, + // any subsequent warnings will be withhold for 1 minute to don't overwhelm the user. + if int64(db.writeDelayMeter.Rate1()) > writeDelayThreshold.Nanoseconds() && + time.Now().After(lastWriteDelay.Add(writeDelayWarningThrottler)) { + db.log.Warn("Write delay duration exceeds the threshold (0.35sec) in the last minute") + lastWriteDelay = time.Now() } }