From b8547734ae50c43adde62e6dff7f4d2c47604942 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 11:53:40 -0700 Subject: [PATCH 1/9] etcdserver: add "etcd_server_heartbeat_failures_total" {"level":"warn","ts":1527101858.4149103,"caller":"etcdserver/raft.go:370","msg":"failed to send out heartbeat; took too long, server is overloaded likely from slow disk","heartbeat-interval":0.1,"expected-duration":0.2,"exceeded-duration":0.025771662} {"level":"warn","ts":1527101858.4149644,"caller":"etcdserver/raft.go:370","msg":"failed to send out heartbeat; took too long, server is overloaded likely from slow disk","heartbeat-interval":0.1,"expected-duration":0.2,"exceeded-duration":0.034015766} Signed-off-by: Gyuho Lee --- etcdserver/metrics.go | 7 +++++++ etcdserver/raft.go | 1 + 2 files changed, 8 insertions(+) diff --git a/etcdserver/metrics.go b/etcdserver/metrics.go index 88ff158b7cd..7d57b81159e 100644 --- a/etcdserver/metrics.go +++ b/etcdserver/metrics.go @@ -41,6 +41,12 @@ var ( Name: "leader_changes_seen_total", Help: "The number of leader changes seen.", }) + heartbeatFailures = prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: "etcd", + Subsystem: "server", + Name: "heartbeat_failures_total", + Help: "The total number of heartbeat send failures (likely overloaded from slow disk).", + }) proposalsCommitted = prometheus.NewGauge(prometheus.GaugeOpts{ Namespace: "etcd", Subsystem: "server", @@ -90,6 +96,7 @@ func init() { prometheus.MustRegister(hasLeader) prometheus.MustRegister(isLeader) prometheus.MustRegister(leaderChanges) + prometheus.MustRegister(heartbeatFailures) prometheus.MustRegister(proposalsCommitted) prometheus.MustRegister(proposalsApplied) prometheus.MustRegister(proposalsPending) diff --git a/etcdserver/raft.go b/etcdserver/raft.go index 45733512fd1..e69dfc504c3 100644 --- a/etcdserver/raft.go +++ b/etcdserver/raft.go @@ -293,6 +293,7 @@ func (r *raftNode) sendMessages(ms []raftpb.Message) { // TODO: limit request rate. plog.Warningf("failed to send out heartbeat on time (exceeded the %v timeout for %v)", r.heartbeat, exceed) plog.Warningf("server is likely overloaded") + heartbeatFailures.Inc() } } } From 3f1fe618ad466469e2037fdc71e4305835a4d8fe Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:01:38 -0700 Subject: [PATCH 2/9] etcdserver: add "etcd_server_slow_apply_total" {"level":"warn","ts":1527101858.6985068,"caller":"etcdserver/util.go:115","msg":"apply request took too long","took":0.114101529,"expected-duration":0.1,"prefix":"","request":"header: put: --- etcdserver/metrics.go | 7 +++++++ etcdserver/util.go | 1 + 2 files changed, 8 insertions(+) diff --git a/etcdserver/metrics.go b/etcdserver/metrics.go index 7d57b81159e..8675d0ca248 100644 --- a/etcdserver/metrics.go +++ b/etcdserver/metrics.go @@ -47,6 +47,12 @@ var ( Name: "heartbeat_failures_total", Help: "The total number of heartbeat send failures (likely overloaded from slow disk).", }) + slowApplies = prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: "etcd", + Subsystem: "server", + Name: "slow_apply_total", + Help: "The total number of slow apply requests (likely overloaded from slow disk).", + }) proposalsCommitted = prometheus.NewGauge(prometheus.GaugeOpts{ Namespace: "etcd", Subsystem: "server", @@ -97,6 +103,7 @@ func init() { prometheus.MustRegister(isLeader) prometheus.MustRegister(leaderChanges) prometheus.MustRegister(heartbeatFailures) + prometheus.MustRegister(slowApplies) prometheus.MustRegister(proposalsCommitted) prometheus.MustRegister(proposalsApplied) prometheus.MustRegister(proposalsPending) diff --git a/etcdserver/util.go b/etcdserver/util.go index d3f69e09ecd..b8a325a7561 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -146,6 +146,7 @@ func warnOfExpensiveGenericRequest(now time.Time, reqStringer fmt.Stringer, pref result = resp } plog.Warningf("%srequest %q with result %q took too long (%v) to execute", prefix, reqStringer.String(), result, d) + slowApplies.Inc() } } From 92a7b5df809f29fe894903f95bb76796f15c5960 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:09:03 -0700 Subject: [PATCH 3/9] mvcc/backend: clean up mutex, logging Signed-off-by: Gyuho Lee --- mvcc/backend/batch_tx.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/mvcc/backend/batch_tx.go b/mvcc/backend/batch_tx.go index 91ac1338a97..66a5ff1db51 100644 --- a/mvcc/backend/batch_tx.go +++ b/mvcc/backend/batch_tx.go @@ -136,15 +136,15 @@ func (t *batchTx) UnsafeForEach(bucketName []byte, visitor func(k, v []byte) err // Commit commits a previous tx and begins a new writable one. func (t *batchTx) Commit() { t.Lock() - defer t.Unlock() t.commit(false) + t.Unlock() } // CommitAndStop commits the previous tx and do not create a new one. func (t *batchTx) CommitAndStop() { t.Lock() - defer t.Unlock() t.commit(true) + t.Unlock() } func (t *batchTx) Unlock() { @@ -163,9 +163,11 @@ func (t *batchTx) commit(stop bool) { return } start := time.Now() + // gofail: var beforeCommit struct{} err = t.tx.Commit() // gofail: var afterCommit struct{} + commitDurations.Observe(time.Since(start).Seconds()) atomic.AddInt64(&t.backend.commits, 1) From 22c25dd4e7b1f5fb0849a07a14142232951cf394 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:14:43 -0700 Subject: [PATCH 4/9] mvcc/backend: document metrics ExponentialBuckets Signed-off-by: Gyuho Lee --- mvcc/backend/metrics.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/mvcc/backend/metrics.go b/mvcc/backend/metrics.go index 34a56a91956..76fcb9cf2d1 100644 --- a/mvcc/backend/metrics.go +++ b/mvcc/backend/metrics.go @@ -22,7 +22,10 @@ var ( Subsystem: "disk", Name: "backend_commit_duration_seconds", Help: "The latency distributions of commit called by backend.", - Buckets: prometheus.ExponentialBuckets(0.001, 2, 14), + + // lowest bucket start of upper bound 0.001 sec (1 ms) with factor 2 + // highest bucket start of 0.001 sec * 2^13 == 8.192 sec + Buckets: prometheus.ExponentialBuckets(0.001, 2, 14), }) ) From 9f58e57a3c54370eddea6b545500738100d4779e Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:21:57 -0700 Subject: [PATCH 5/9] mvcc/backend: add "etcd_disk_backend_defrag_duration_seconds" Signed-off-by: Gyuho Lee --- mvcc/backend/backend.go | 5 +++++ mvcc/backend/metrics.go | 13 +++++++++++++ 2 files changed, 18 insertions(+) diff --git a/mvcc/backend/backend.go b/mvcc/backend/backend.go index cea328ca319..9a6d2ac9a3e 100644 --- a/mvcc/backend/backend.go +++ b/mvcc/backend/backend.go @@ -229,6 +229,8 @@ func (b *backend) Defrag() error { } func (b *backend) defrag() error { + now := time.Now() + // TODO: make this non-blocking? // lock batchTx to ensure nobody is using previous tx, and then // close previous ongoing tx. @@ -285,6 +287,9 @@ func (b *backend) defrag() error { atomic.StoreInt64(&b.size, size) atomic.StoreInt64(&b.sizeInUse, size-(int64(db.Stats().FreePageN)*int64(db.Info().PageSize))) + took := time.Since(now) + defragDurations.Observe(took.Seconds()) + return nil } diff --git a/mvcc/backend/metrics.go b/mvcc/backend/metrics.go index 76fcb9cf2d1..b266d1e0f8e 100644 --- a/mvcc/backend/metrics.go +++ b/mvcc/backend/metrics.go @@ -27,8 +27,21 @@ var ( // highest bucket start of 0.001 sec * 2^13 == 8.192 sec Buckets: prometheus.ExponentialBuckets(0.001, 2, 14), }) + + defragDurations = prometheus.NewHistogram(prometheus.HistogramOpts{ + Namespace: "etcd", + Subsystem: "disk", + Name: "backend_defrag_duration_seconds", + Help: "The latency distribution of backend defragmentation.", + + // 100 MB usually takes 1 sec, so start with 10 MB of 100 ms + // lowest bucket start of upper bound 0.1 sec (100 ms) with factor 2 + // highest bucket start of 0.1 sec * 2^12 == 409.6 sec + Buckets: prometheus.ExponentialBuckets(.01, 2, 13), + }) ) func init() { prometheus.MustRegister(commitDurations) + prometheus.MustRegister(defragDurations) } From cac6ce756d49e64195a436a0000145fe68426f0e Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:33:58 -0700 Subject: [PATCH 6/9] mvcc/backend: fix defrag duration scale Signed-off-by: Gyuho Lee --- mvcc/backend/metrics.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mvcc/backend/metrics.go b/mvcc/backend/metrics.go index b266d1e0f8e..d2a4debf72d 100644 --- a/mvcc/backend/metrics.go +++ b/mvcc/backend/metrics.go @@ -37,7 +37,7 @@ var ( // 100 MB usually takes 1 sec, so start with 10 MB of 100 ms // lowest bucket start of upper bound 0.1 sec (100 ms) with factor 2 // highest bucket start of 0.1 sec * 2^12 == 409.6 sec - Buckets: prometheus.ExponentialBuckets(.01, 2, 13), + Buckets: prometheus.ExponentialBuckets(.1, 2, 13), }) ) From fb5080b306c59b871d201494fe4add1c56ecca98 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 12:34:09 -0700 Subject: [PATCH 7/9] mvcc: add "etcd_mvcc_hash_(rev)_duration_seconds" etcd_mvcc_hash_duration_seconds etcd_mvcc_hash_rev_duration_seconds Signed-off-by: Gyuho Lee --- mvcc/kvstore.go | 5 +++++ mvcc/metrics.go | 16 +++++++++++++++- 2 files changed, 20 insertions(+), 1 deletion(-) diff --git a/mvcc/kvstore.go b/mvcc/kvstore.go index 963d821e518..54dcedcf67f 100644 --- a/mvcc/kvstore.go +++ b/mvcc/kvstore.go @@ -335,9 +335,14 @@ func init() { func (s *store) Hash() (uint32, int64, error) { s.mu.Lock() defer s.mu.Unlock() + + start := time.Now() + s.b.ForceCommit() h, err := s.b.Hash(DefaultIgnores) + + hashDurations.Observe(time.Since(start).Seconds()) rev := s.currentRev.main return h, rev, err } diff --git a/mvcc/metrics.go b/mvcc/metrics.go index 0d5898c0b63..f3b52426b7a 100644 --- a/mvcc/metrics.go +++ b/mvcc/metrics.go @@ -175,7 +175,19 @@ var ( ) // overridden by mvcc initialization reportDbTotalSizeInUseInBytesMu sync.RWMutex - reportDbTotalSizeInUseInBytes = func() float64 { return 0 } + reportDbTotalSizeInUseInBytes func() float64 = func() float64 { return 0 } + + hashDurations = prometheus.NewHistogram(prometheus.HistogramOpts{ + Namespace: "etcd", + Subsystem: "mvcc", + Name: "hash_duration_seconds", + Help: "The latency distribution of storage hash operation.", + + // 100 MB usually takes 100 ms, so start with 10 MB of 10 ms + // lowest bucket start of upper bound 0.01 sec (10 ms) with factor 2 + // highest bucket start of 0.01 sec * 2^14 == 163.84 sec + Buckets: prometheus.ExponentialBuckets(.01, 2, 15), + }) ) func init() { @@ -195,6 +207,8 @@ func init() { prometheus.MustRegister(dbTotalSizeDebugging) prometheus.MustRegister(dbTotalSize) prometheus.MustRegister(dbTotalSizeInUse) + prometheus.MustRegister(hashDurations) + prometheus.MustRegister(hashRevDurations) } // ReportEventReceived reports that an event is received. From 0fbf49df11cfe31831e978d087f3cfee17c2f9a5 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 23 May 2018 13:09:31 -0700 Subject: [PATCH 8/9] etcdserver: rename to "heartbeat_send_failures_total" Signed-off-by: Gyuho Lee --- etcdserver/metrics.go | 8 ++++---- etcdserver/raft.go | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/etcdserver/metrics.go b/etcdserver/metrics.go index 8675d0ca248..b4575feb7db 100644 --- a/etcdserver/metrics.go +++ b/etcdserver/metrics.go @@ -41,11 +41,11 @@ var ( Name: "leader_changes_seen_total", Help: "The number of leader changes seen.", }) - heartbeatFailures = prometheus.NewCounter(prometheus.CounterOpts{ + heartbeatSendFailures = prometheus.NewCounter(prometheus.CounterOpts{ Namespace: "etcd", Subsystem: "server", - Name: "heartbeat_failures_total", - Help: "The total number of heartbeat send failures (likely overloaded from slow disk).", + Name: "heartbeat_send_failures_total", + Help: "The total number of leader heartbeat send failures (likely overloaded from slow disk).", }) slowApplies = prometheus.NewCounter(prometheus.CounterOpts{ Namespace: "etcd", @@ -102,7 +102,7 @@ func init() { prometheus.MustRegister(hasLeader) prometheus.MustRegister(isLeader) prometheus.MustRegister(leaderChanges) - prometheus.MustRegister(heartbeatFailures) + prometheus.MustRegister(heartbeatSendFailures) prometheus.MustRegister(slowApplies) prometheus.MustRegister(proposalsCommitted) prometheus.MustRegister(proposalsApplied) diff --git a/etcdserver/raft.go b/etcdserver/raft.go index e69dfc504c3..1d40904dc73 100644 --- a/etcdserver/raft.go +++ b/etcdserver/raft.go @@ -293,7 +293,7 @@ func (r *raftNode) sendMessages(ms []raftpb.Message) { // TODO: limit request rate. plog.Warningf("failed to send out heartbeat on time (exceeded the %v timeout for %v)", r.heartbeat, exceed) plog.Warningf("server is likely overloaded") - heartbeatFailures.Inc() + heartbeatSendFailures.Inc() } } } From a421a604d6a8c059b4d839e71c35c3feb7c80d42 Mon Sep 17 00:00:00 2001 From: Wenjia Date: Fri, 20 Jul 2018 13:49:58 -0700 Subject: [PATCH 9/9] remove hashRevDurations --- mvcc/metrics.go | 1 - 1 file changed, 1 deletion(-) diff --git a/mvcc/metrics.go b/mvcc/metrics.go index f3b52426b7a..bcef27b8a40 100644 --- a/mvcc/metrics.go +++ b/mvcc/metrics.go @@ -208,7 +208,6 @@ func init() { prometheus.MustRegister(dbTotalSize) prometheus.MustRegister(dbTotalSizeInUse) prometheus.MustRegister(hashDurations) - prometheus.MustRegister(hashRevDurations) } // ReportEventReceived reports that an event is received.