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