From df000fd776d5c83847f750b6928827a2b30eeca9 Mon Sep 17 00:00:00 2001
From: Xiang <xiangli.cs@gmail.com>
Date: Tue, 6 Feb 2018 12:15:52 -0800
Subject: [PATCH] etcdserver: improve request took too long warning

---
 etcdserver/apply.go     |  2 ++
 etcdserver/apply_v2.go  |  2 ++
 etcdserver/server.go    |  8 +-------
 etcdserver/util.go      | 17 +++++++++++++++++
 etcdserver/v2_server.go |  5 +++++
 etcdserver/v3_server.go |  5 +++++
 6 files changed, 32 insertions(+), 7 deletions(-)

diff --git a/etcdserver/apply.go b/etcdserver/apply.go
index e4bf35bc47e..25e8c557ff1 100644
--- a/etcdserver/apply.go
+++ b/etcdserver/apply.go
@@ -94,6 +94,8 @@ func (s *EtcdServer) newApplierV3() applierV3 {
 }
 
 func (a *applierV3backend) Apply(r *pb.InternalRaftRequest) *applyResult {
+	defer warnOfExpensiveRequest(time.Now(), r)
+
 	ar := &applyResult{}
 
 	// call into a.s.applyV3.F instead of a.F so upper appliers can check individual calls
diff --git a/etcdserver/apply_v2.go b/etcdserver/apply_v2.go
index f278efca88e..57e4b8f2e30 100644
--- a/etcdserver/apply_v2.go
+++ b/etcdserver/apply_v2.go
@@ -108,7 +108,9 @@ func (a *applierV2store) Sync(r *pb.Request) Response {
 // applyV2Request interprets r as a call to store.X and returns a Response interpreted
 // from store.Event
 func (s *EtcdServer) applyV2Request(r *pb.Request) Response {
+	defer warnOfExpensiveRequest(time.Now(), r)
 	toTTLOptions(r)
+
 	switch r.Method {
 	case "POST":
 		return s.applyV2.Post(r)
diff --git a/etcdserver/server.go b/etcdserver/server.go
index f54e15071a3..7167a76dbfc 100644
--- a/etcdserver/server.go
+++ b/etcdserver/server.go
@@ -800,14 +800,8 @@ func (s *EtcdServer) run() {
 
 func (s *EtcdServer) applyAll(ep *etcdProgress, apply *apply) {
 	s.applySnapshot(ep, apply)
-	st := time.Now()
 	s.applyEntries(ep, apply)
-	d := time.Since(st)
-	entriesNum := len(apply.entries)
-	if entriesNum != 0 && d > time.Duration(entriesNum)*warnApplyDuration {
-		plog.Warningf("apply entries took too long [%v for %d entries]", d, len(apply.entries))
-		plog.Warningf("avoid queries with large range/delete range!")
-	}
+
 	proposalsApplied.Set(float64(ep.appliedi))
 	s.applyWait.Trigger(ep.appliedi)
 	// wait for the raft routine to finish the disk writes before triggering a
diff --git a/etcdserver/util.go b/etcdserver/util.go
index 66084ae1244..0bce97cab13 100644
--- a/etcdserver/util.go
+++ b/etcdserver/util.go
@@ -15,6 +15,7 @@
 package etcdserver
 
 import (
+	"fmt"
 	"time"
 
 	"github.com/coreos/etcd/etcdserver/membership"
@@ -95,3 +96,19 @@ func (nc *notifier) notify(err error) {
 	nc.err = err
 	close(nc.c)
 }
+
+func warnOfExpensiveRequest(now time.Time, stringer fmt.Stringer) {
+	warnOfExpensiveGenericRequest(now, stringer, "")
+}
+
+func warnOfExpensiveReadOnlyRangeRequest(now time.Time, stringer fmt.Stringer) {
+	warnOfExpensiveGenericRequest(now, stringer, "read-only range ")
+}
+
+func warnOfExpensiveGenericRequest(now time.Time, stringer fmt.Stringer, prefix string) {
+	// TODO: add metrics
+	d := time.Since(now)
+	if d > warnApplyDuration {
+		plog.Warningf("%srequest %q took too long (%v) to execute", prefix, stringer.String(), d)
+	}
+}
diff --git a/etcdserver/v2_server.go b/etcdserver/v2_server.go
index 72c4eb7c5cc..8706c746db5 100644
--- a/etcdserver/v2_server.go
+++ b/etcdserver/v2_server.go
@@ -123,3 +123,8 @@ func (s *EtcdServer) Do(ctx context.Context, r pb.Request) (Response, error) {
 	}
 	return Response{}, ErrUnknownMethod
 }
+
+func (r *RequestV2) String() string {
+	rpb := pb.Request(*r)
+	return rpb.String()
+}
diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go
index 60653cb6dff..ba171094071 100644
--- a/etcdserver/v3_server.go
+++ b/etcdserver/v3_server.go
@@ -95,6 +95,7 @@ func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeRe
 	if s.ClusterVersion() == nil || s.ClusterVersion().LessThan(newRangeClusterVersion) {
 		return s.legacyRange(ctx, r)
 	}
+	defer warnOfExpensiveReadOnlyRangeRequest(time.Now(), r)
 
 	if !r.Serializable {
 		err := s.linearizableReadNotify(ctx)
@@ -108,6 +109,7 @@ func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeRe
 		return s.authStore.IsRangePermitted(ai, r.Key, r.RangeEnd)
 	}
 	get := func() { resp, err = s.applyV3Base.Range(noTxn, r) }
+	get := func() { resp, err = s.applyV3Base.Range(nil, r) }
 	if serr := s.doSerialize(ctx, chk, get); serr != nil {
 		return nil, serr
 	}
@@ -178,6 +180,9 @@ func (s *EtcdServer) Txn(ctx context.Context, r *pb.TxnRequest) (*pb.TxnResponse
 		chk := func(ai *auth.AuthInfo) error {
 			return checkTxnAuth(s.authStore, ai, r)
 		}
+
+		defer warnOfExpensiveReadOnlyRangeRequest(time.Now(), r)
+
 		get := func() { resp, err = s.applyV3Base.Txn(r) }
 		if serr := s.doSerialize(ctx, chk, get); serr != nil {
 			return nil, serr