From 23c5c71426d3508c4ecd8f1b5a0990b0c22a0b31 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 | 5 +- etcdserver/apply_v2.go | 6 +-- .../etcdserverpb/raft_internal_stringer.go | 16 ++---- etcdserver/util.go | 51 ++++++++++++++++--- etcdserver/v3_server.go | 20 ++++---- 5 files changed, 66 insertions(+), 32 deletions(-) diff --git a/etcdserver/apply.go b/etcdserver/apply.go index 071f587c2..928a70d9c 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -94,9 +94,10 @@ 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) { + warnOfExpensiveRequest(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 57e4b8f2e..67f30a0bb 100644 --- a/etcdserver/apply_v2.go +++ b/etcdserver/apply_v2.go @@ -105,10 +105,10 @@ func (a *applierV2store) Sync(r *pb.Request) Response { return Response{} } -// applyV2Request interprets r as a call to store.X and returns a Response interpreted -// from store.Event +// applyV2Request interprets r as a call to v2store.X +// and returns a Response interpreted from v2store.Event func (s *EtcdServer) applyV2Request(r *pb.Request) Response { - defer warnOfExpensiveRequest(time.Now(), r) + defer warnOfExpensiveRequest(time.Now(), r, nil, nil) toTTLOptions(r) switch r.Method { diff --git a/etcdserver/etcdserverpb/raft_internal_stringer.go b/etcdserver/etcdserverpb/raft_internal_stringer.go index de9057a09..18d9ec843 100644 --- a/etcdserver/etcdserverpb/raft_internal_stringer.go +++ b/etcdserver/etcdserverpb/raft_internal_stringer.go @@ -122,8 +122,6 @@ func (as *requestOpStringer) String() string { switch op := as.Op.Request.(type) { case *RequestOp_RequestPut: return fmt.Sprintf("request_put:<%s>", newLoggablePutRequest(op.RequestPut).String()) - case *RequestOp_RequestTxn: - return fmt.Sprintf("request_txn:<%s>", newLoggableTxnRequest(op.RequestTxn).String()) default: // nothing to redact } @@ -138,7 +136,6 @@ type loggableValueCompare struct { Target Compare_CompareTarget `protobuf:"varint,2,opt,name=target,proto3,enum=etcdserverpb.Compare_CompareTarget"` Key []byte `protobuf:"bytes,3,opt,name=key,proto3"` ValueSize int `protobuf:"bytes,7,opt,name=value_size,proto3"` - RangeEnd []byte `protobuf:"bytes,64,opt,name=range_end,proto3"` } func newLoggableValueCompare(c *Compare, cv *Compare_Value) *loggableValueCompare { @@ -147,7 +144,6 @@ func newLoggableValueCompare(c *Compare, cv *Compare_Value) *loggableValueCompar c.Target, c.Key, len(cv.Value), - c.RangeEnd, } } @@ -159,12 +155,10 @@ func (*loggableValueCompare) ProtoMessage() {} // size field. // To preserve proto encoding of the key bytes, a faked out proto type is used here. type loggablePutRequest struct { - Key []byte `protobuf:"bytes,1,opt,name=key,proto3"` - ValueSize int `protobuf:"varint,2,opt,name=value_size,proto3"` - Lease int64 `protobuf:"varint,3,opt,name=lease,proto3"` - PrevKv bool `protobuf:"varint,4,opt,name=prev_kv,proto3"` - IgnoreValue bool `protobuf:"varint,5,opt,name=ignore_value,proto3"` - IgnoreLease bool `protobuf:"varint,6,opt,name=ignore_lease,proto3"` + Key []byte `protobuf:"bytes,1,opt,name=key,proto3"` + ValueSize int `protobuf:"varint,2,opt,name=value_size,proto3"` + Lease int64 `protobuf:"varint,3,opt,name=lease,proto3"` + PrevKv bool `protobuf:"varint,4,opt,name=prev_kv,proto3"` } func newLoggablePutRequest(request *PutRequest) *loggablePutRequest { @@ -173,8 +167,6 @@ func newLoggablePutRequest(request *PutRequest) *loggablePutRequest { len(request.Value), request.Lease, request.PrevKv, - request.IgnoreValue, - request.IgnoreLease, } } diff --git a/etcdserver/util.go b/etcdserver/util.go index 0bce97cab..84f68ce35 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -16,11 +16,15 @@ package etcdserver import ( "fmt" + "reflect" + "strings" "time" + pb "github.com/coreos/etcd/etcdserver/etcdserverpb" "github.com/coreos/etcd/etcdserver/membership" "github.com/coreos/etcd/pkg/types" "github.com/coreos/etcd/rafthttp" + "github.com/golang/protobuf/proto" ) // isConnectedToQuorumSince checks whether the local member is connected to the @@ -97,18 +101,53 @@ func (nc *notifier) notify(err error) { close(nc.c) } -func warnOfExpensiveRequest(now time.Time, stringer fmt.Stringer) { - warnOfExpensiveGenericRequest(now, stringer, "") +func warnOfExpensiveRequest(now time.Time, reqStringer fmt.Stringer, respMsg proto.Message, err error) { + var resp string + if !isNil(respMsg) { + resp = fmt.Sprintf("size:%d", proto.Size(respMsg)) + } + warnOfExpensiveGenericRequest(now, reqStringer, "", resp, err) } -func warnOfExpensiveReadOnlyRangeRequest(now time.Time, stringer fmt.Stringer) { - warnOfExpensiveGenericRequest(now, stringer, "read-only range ") +func warnOfExpensiveReadOnlyTxnRequest(now time.Time, reqStringer fmt.Stringer, txnResponse *pb.TxnResponse, err error) { + var resp string + if !isNil(txnResponse) { + var resps []string + for _, r := range txnResponse.Responses { + switch op := r.Response.(type) { + case *pb.ResponseOp_ResponseRange: + resps = append(resps, fmt.Sprintf("range_response_count:%d", len(op.ResponseRange.Kvs))) + default: + // only range responses should be in a read only txn request + } + } + resp = fmt.Sprintf("responses:<%s> size:%d", strings.Join(resps, " "), proto.Size(txnResponse)) + } + warnOfExpensiveGenericRequest(now, reqStringer, "read-only range ", resp, err) } -func warnOfExpensiveGenericRequest(now time.Time, stringer fmt.Stringer, prefix string) { +func warnOfExpensiveReadOnlyRangeRequest(now time.Time, reqStringer fmt.Stringer, rangeResponse *pb.RangeResponse, err error) { + var resp string + if !isNil(rangeResponse) { + resp = fmt.Sprintf("range_response_count:%d size:%d", len(rangeResponse.Kvs), proto.Size(rangeResponse)) + } + warnOfExpensiveGenericRequest(now, reqStringer, "read-only range ", resp, err) +} + +func warnOfExpensiveGenericRequest(now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) { // TODO: add metrics d := time.Since(now) if d > warnApplyDuration { - plog.Warningf("%srequest %q took too long (%v) to execute", prefix, stringer.String(), d) + var result string + if err != nil { + result = fmt.Sprintf("error:%v", err) + } else { + result = resp + } + plog.Warningf("%srequest %q with result %q took too long (%v) to execute", prefix, reqStringer.String(), result, d) } } + +func isNil(msg proto.Message) bool { + return msg == nil || reflect.ValueOf(msg).IsNil() +} diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index c5d0ecb9b..cd07f63a0 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -26,10 +26,8 @@ import ( "github.com/coreos/etcd/lease/leasehttp" "github.com/coreos/etcd/mvcc" "github.com/coreos/etcd/raft" - "github.com/gogo/protobuf/proto" "github.com/coreos/go-semver/semver" - "github.com/gogo/protobuf/proto" "golang.org/x/net/context" ) @@ -97,23 +95,25 @@ 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) + var resp *pb.RangeResponse + var err error + defer func(start time.Time) { + warnOfExpensiveReadOnlyRangeRequest(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(noTxn, r) } - get := func() { resp, err = s.applyV3Base.Range(nil, r) } if serr := s.doSerialize(ctx, chk, get); serr != nil { - return nil, serr + err = serr + return nil, err } return resp, err } @@ -183,7 +183,9 @@ func (s *EtcdServer) Txn(ctx context.Context, r *pb.TxnRequest) (*pb.TxnResponse return checkTxnAuth(s.authStore, ai, r) } - defer warnOfExpensiveReadOnlyRangeRequest(time.Now(), r) + defer func(start time.Time) { + warnOfExpensiveReadOnlyTxnRequest(start, r, resp, err) + }(time.Now()) get := func() { resp, err = s.applyV3Base.Txn(r) } if serr := s.doSerialize(ctx, chk, get); serr != nil {