From 50e9b0338499ad30fff022e16306c2ac40dd88bd Mon Sep 17 00:00:00 2001 From: Joe Betz Date: Thu, 7 Jun 2018 22:44:46 -0700 Subject: [PATCH] etcdserver: Add response byte size and range response count to took too long warning --- etcdserver/apply.go | 7 +++-- etcdserver/apply_v2.go | 2 +- etcdserver/util.go | 61 ++++++++++++++++++++++++++++++++++++----- etcdserver/v3_server.go | 18 +++++++----- 4 files changed, 71 insertions(+), 17 deletions(-) diff --git a/etcdserver/apply.go b/etcdserver/apply.go index 63379dec89bd..a6d1659b63c9 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -109,9 +109,12 @@ func (s *EtcdServer) newApplierV3() applierV3 { } func (a *applierV3backend) Apply(r *pb.InternalRaftRequest) *applyResult { - defer warnOfExpensiveRequest(a.s.getLogger(), time.Now(), &pb.InternalRaftStringer{Request: r}) - ar := &applyResult{} + defer func(start time.Time) { + if ar != nil { // should never be nil, but just to be safe + warnOfExpensiveRequest(a.s.getLogger(), start, &pb.InternalRaftStringer{Request: r}, ar.resp, ar.err) + } + }(time.Now()) // call into a.s.applyV3.F instead of a.F so upper appliers can check individual calls switch { diff --git a/etcdserver/apply_v2.go b/etcdserver/apply_v2.go index 89d3ccfb3b7f..ab0e854c8f9c 100644 --- a/etcdserver/apply_v2.go +++ b/etcdserver/apply_v2.go @@ -114,7 +114,7 @@ func (a *applierV2store) Sync(r *RequestV2) Response { // applyV2Request interprets r as a call to v2store.X // and returns a Response interpreted from v2store.Event func (s *EtcdServer) applyV2Request(r *RequestV2) Response { - defer warnOfExpensiveRequest(s.getLogger(), time.Now(), r) + defer warnOfExpensiveRequest(s.getLogger(), time.Now(), r, nil, nil) switch r.Method { case "POST": diff --git a/etcdserver/util.go b/etcdserver/util.go index e05884f59736..5dccc22b0420 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -16,11 +16,14 @@ package etcdserver import ( "fmt" + "strings" "time" "github.com/coreos/etcd/etcdserver/api/membership" "github.com/coreos/etcd/etcdserver/api/rafthttp" + pb "github.com/coreos/etcd/etcdserver/etcdserverpb" "github.com/coreos/etcd/pkg/types" + "github.com/golang/protobuf/proto" "go.uber.org/zap" ) @@ -99,15 +102,40 @@ func (nc *notifier) notify(err error) { close(nc.c) } -func warnOfExpensiveRequest(lg *zap.Logger, now time.Time, stringer fmt.Stringer) { - warnOfExpensiveGenericRequest(lg, now, stringer, "") +func warnOfExpensiveRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, respMsg proto.Message, err error) { + var resp string + if respMsg != nil { + resp = fmt.Sprintf("", safeSize(respMsg)) + } + warnOfExpensiveGenericRequest(lg, now, reqStringer, "", resp, err) } -func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, now time.Time, stringer fmt.Stringer) { - warnOfExpensiveGenericRequest(lg, now, stringer, "read-only range ") +func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, txnResponse *pb.TxnResponse, err error) { + var resp string + if txnResponse != nil { + var resps []string + for _, r := range txnResponse.Responses { + switch op := r.Response.(type) { + case *pb.ResponseOp_ResponseRange: + resps = append(resps, fmt.Sprintf("", len(op.ResponseRange.Kvs))) + default: + // only range responses should be in a read only txn request + } + } + resp = fmt.Sprintf(" size:%d>", strings.Join(resps, " "), safeSize(txnResponse)) + } + warnOfExpensiveGenericRequest(lg, now, reqStringer, "read-only range ", resp, err) } -func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, stringer fmt.Stringer, prefix string) { +func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, rangeResponse *pb.RangeResponse, err error) { + var resp string + if rangeResponse != nil { + resp = fmt.Sprintf("", len(rangeResponse.Kvs), safeSize(rangeResponse)) + } + warnOfExpensiveGenericRequest(lg, now, reqStringer, "read-only range ", resp, err) +} + +func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) { // TODO: add metrics d := time.Since(now) if d > warnApplyDuration { @@ -117,11 +145,30 @@ func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, stringer fmt.S zap.Duration("took", d), zap.Duration("expected-duration", warnApplyDuration), zap.String("prefix", prefix), - zap.String("request", stringer.String()), + zap.String("request", reqStringer.String()), + zap.String("response", resp), + zap.Error(err), ) } else { - plog.Warningf("%srequest %q took too long (%v) to execute", prefix, stringer.String(), d) + var result string + if err != nil { + result = fmt.Sprintf("", err) + } else { + result = resp + } + plog.Warningf("%srequest %q with result %q took too long (%v) to execute", prefix, reqStringer.String(), result, d) } slowApplies.Inc() } } + +// safeSize attempt to calculate size using proto.Size, but recovers from panics and return -1 in those cases. +// TODO: Remove once https://github.com/golang/protobuf/issues/631 is resolved. +func safeSize(msg proto.Message) (size int) { + defer func() { + if r := recover(); r != nil { + size = -1 + } + }() + return proto.Size(msg) +} diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index 13b9bff0d746..b8a98be536f1 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -86,23 +86,25 @@ type Authenticator interface { } func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeResponse, error) { - defer warnOfExpensiveReadOnlyRangeRequest(s.getLogger(), time.Now(), r) + var resp *pb.RangeResponse + var err error + defer func(start time.Time) { + warnOfExpensiveReadOnlyRangeRequest(s.getLogger(), start, r, resp, err) + }(time.Now()) if !r.Serializable { - err := s.linearizableReadNotify(ctx) + err = s.linearizableReadNotify(ctx) if err != nil { return nil, err } } - var resp *pb.RangeResponse - var err error chk := func(ai *auth.AuthInfo) error { return s.authStore.IsRangePermitted(ai, r.Key, r.RangeEnd) } get := func() { resp, err = s.applyV3Base.Range(nil, r) } - if serr := s.doSerialize(ctx, chk, get); serr != nil { - return nil, serr + if err = s.doSerialize(ctx, chk, get); err != nil { + return nil, err } return resp, err } @@ -137,7 +139,9 @@ func (s *EtcdServer) Txn(ctx context.Context, r *pb.TxnRequest) (*pb.TxnResponse return checkTxnAuth(s.authStore, ai, r) } - defer warnOfExpensiveReadOnlyRangeRequest(s.getLogger(), time.Now(), r) + defer func(start time.Time) { + warnOfExpensiveReadOnlyTxnRequest(s.getLogger(), start, r, resp, err) + }(time.Now()) get := func() { resp, err = s.applyV3Base.Txn(r) } if serr := s.doSerialize(ctx, chk, get); serr != nil {