From 1935a663df21cc184c0d7653634cb823c2571284 Mon Sep 17 00:00:00 2001 From: Xiang Date: Tue, 6 Feb 2018 12:15:52 -0800 Subject: [PATCH 1/6] 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 | 7 +++++++ 6 files changed, 34 insertions(+), 7 deletions(-) diff --git a/etcdserver/apply.go b/etcdserver/apply.go index 0be93c52b6f..9148f5692f8 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -88,6 +88,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 e652f456e3a..a8a38129264 100644 --- a/etcdserver/server.go +++ b/etcdserver/server.go @@ -818,14 +818,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 e3896ffc2d3..f1ba2dbecf4 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 ae449bbf22f..282ad380eee 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -82,6 +82,8 @@ type Authenticator interface { } func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeResponse, error) { + defer warnOfExpensiveReadOnlyRangeRequest(time.Now(), r) + if !r.Serializable { err := s.linearizableReadNotify(ctx) if err != nil { @@ -93,6 +95,7 @@ func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeRe 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 @@ -129,12 +132,16 @@ 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 } return resp, err } + resp, err := s.raftRequest(ctx, pb.InternalRaftRequest{Txn: r}) if err != nil { return nil, err From 065053d859a79e6febdd2dd9e5b015384a82bb02 Mon Sep 17 00:00:00 2001 From: Joe Betz Date: Thu, 7 Jun 2018 11:02:00 -0700 Subject: [PATCH 2/6] etcdserver: Fix to backport of #9288 for pre-RequestV2 code --- etcdserver/v2_server.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/etcdserver/v2_server.go b/etcdserver/v2_server.go index 8706c746db5..72c4eb7c5cc 100644 --- a/etcdserver/v2_server.go +++ b/etcdserver/v2_server.go @@ -123,8 +123,3 @@ 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() -} From dcf30b1c54b32e732c151bcaf6cf84d9377f4360 Mon Sep 17 00:00:00 2001 From: Hitoshi Mitake Date: Thu, 26 Apr 2018 16:16:36 +0900 Subject: [PATCH 3/6] etcdserver: not print password in the warning message of expensive request Fix https://github.com/coreos/etcd/issues/9635 --- etcdserver/apply.go | 2 +- .../etcdserverpb/raft_internal_stringer.go | 58 +++++++++++++++++++ etcdserver/v3_server.go | 4 +- 3 files changed, 61 insertions(+), 3 deletions(-) create mode 100644 etcdserver/etcdserverpb/raft_internal_stringer.go diff --git a/etcdserver/apply.go b/etcdserver/apply.go index 9148f5692f8..220366ea822 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -88,7 +88,7 @@ func (s *EtcdServer) newApplierV3() applierV3 { } func (a *applierV3backend) Apply(r *pb.InternalRaftRequest) *applyResult { - defer warnOfExpensiveRequest(time.Now(), r) + defer warnOfExpensiveRequest(a.s.getLogger(), time.Now(), &pb.InternalRaftStringer{Request: r}) ar := &applyResult{} diff --git a/etcdserver/etcdserverpb/raft_internal_stringer.go b/etcdserver/etcdserverpb/raft_internal_stringer.go new file mode 100644 index 00000000000..8e1231c23b8 --- /dev/null +++ b/etcdserver/etcdserverpb/raft_internal_stringer.go @@ -0,0 +1,58 @@ +// Copyright 2018 The etcd Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package etcdserverpb + +import "fmt" + +// InternalRaftStringer implements custom proto Stringer: +// redact password, shorten output(TODO). +type InternalRaftStringer struct { + Request *InternalRaftRequest +} + +func (as *InternalRaftStringer) String() string { + switch { + case as.Request.LeaseGrant != nil: + return fmt.Sprintf("header:<%s> lease_grant:", + as.Request.Header.String(), + as.Request.LeaseGrant.TTL, + as.Request.LeaseGrant.ID, + ) + case as.Request.LeaseRevoke != nil: + return fmt.Sprintf("header:<%s> lease_revoke:", + as.Request.Header.String(), + as.Request.LeaseRevoke.ID, + ) + case as.Request.Authenticate != nil: + return fmt.Sprintf("header:<%s> authenticate:", + as.Request.Header.String(), + as.Request.Authenticate.Name, + as.Request.Authenticate.SimpleToken, + ) + case as.Request.AuthUserAdd != nil: + return fmt.Sprintf("header:<%s> auth_user_add:", + as.Request.Header.String(), + as.Request.AuthUserAdd.Name, + ) + case as.Request.AuthUserChangePassword != nil: + return fmt.Sprintf("header:<%s> auth_user_change_password:", + as.Request.Header.String(), + as.Request.AuthUserChangePassword.Name, + ) + default: + // nothing to redact + } + return as.Request.String() +} diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index 282ad380eee..1bd528511fb 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -19,8 +19,6 @@ import ( "encoding/binary" "time" - "github.com/gogo/protobuf/proto" - "github.com/coreos/etcd/auth" pb "github.com/coreos/etcd/etcdserver/etcdserverpb" "github.com/coreos/etcd/etcdserver/membership" @@ -28,7 +26,9 @@ import ( "github.com/coreos/etcd/lease/leasehttp" "github.com/coreos/etcd/mvcc" "github.com/coreos/etcd/raft" + "github.com/gogo/protobuf/proto" + "github.com/gogo/protobuf/proto" "golang.org/x/net/context" ) From 734e4cf8e605b0faceb39dbef1873a8bb0c842ee Mon Sep 17 00:00:00 2001 From: Joe Betz Date: Thu, 7 Jun 2018 14:48:37 -0700 Subject: [PATCH 4/6] etcdserver: Replace value contents with value_size in request took too long warning --- .../etcdserverpb/raft_internal_stringer.go | 129 +++++++++++++++++- 1 file changed, 127 insertions(+), 2 deletions(-) diff --git a/etcdserver/etcdserverpb/raft_internal_stringer.go b/etcdserver/etcdserverpb/raft_internal_stringer.go index 8e1231c23b8..de9057a0937 100644 --- a/etcdserver/etcdserverpb/raft_internal_stringer.go +++ b/etcdserver/etcdserverpb/raft_internal_stringer.go @@ -14,10 +14,15 @@ package etcdserverpb -import "fmt" +import ( + "fmt" + "strings" + + proto "github.com/golang/protobuf/proto" +) // InternalRaftStringer implements custom proto Stringer: -// redact password, shorten output(TODO). +// redact password, replace value fields with value_size fields. type InternalRaftStringer struct { Request *InternalRaftRequest } @@ -51,8 +56,128 @@ func (as *InternalRaftStringer) String() string { as.Request.Header.String(), as.Request.AuthUserChangePassword.Name, ) + case as.Request.Put != nil: + return fmt.Sprintf("header:<%s> put:<%s>", + as.Request.Header.String(), + newLoggablePutRequest(as.Request.Put).String(), + ) + case as.Request.Txn != nil: + return fmt.Sprintf("header:<%s> txn:<%s>", + as.Request.Header.String(), + newLoggableTxnRequest(as.Request.Txn).String(), + ) default: // nothing to redact } return as.Request.String() } + +// txnRequestStringer implements a custom proto String to replace value bytes fields with value size +// fields in any nested txn and put operations. +type txnRequestStringer struct { + Request *TxnRequest +} + +func newLoggableTxnRequest(request *TxnRequest) *txnRequestStringer { + return &txnRequestStringer{request} +} + +func (as *txnRequestStringer) String() string { + var compare []string + for _, c := range as.Request.Compare { + switch cv := c.TargetUnion.(type) { + case *Compare_Value: + compare = append(compare, newLoggableValueCompare(c, cv).String()) + default: + // nothing to redact + compare = append(compare, c.String()) + } + } + var success []string + for _, s := range as.Request.Success { + success = append(success, newLoggableRequestOp(s).String()) + } + var failure []string + for _, f := range as.Request.Failure { + failure = append(failure, newLoggableRequestOp(f).String()) + } + return fmt.Sprintf("compare:<%s> success:<%s> failure:<%s>", + strings.Join(compare, " "), + strings.Join(success, " "), + strings.Join(failure, " "), + ) +} + +// requestOpStringer implements a custom proto String to replace value bytes fields with value +// size fields in any nested txn and put operations. +type requestOpStringer struct { + Op *RequestOp +} + +func newLoggableRequestOp(op *RequestOp) *requestOpStringer { + return &requestOpStringer{op} +} + +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 + } + return as.Op.String() +} + +// loggableValueCompare implements a custom proto String for Compare.Value union member types to +// replace the value bytes field with a value size field. +// To preserve proto encoding of the key and range_end bytes, a faked out proto type is used here. +type loggableValueCompare struct { + Result Compare_CompareResult `protobuf:"varint,1,opt,name=result,proto3,enum=etcdserverpb.Compare_CompareResult"` + 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 { + return &loggableValueCompare{ + c.Result, + c.Target, + c.Key, + len(cv.Value), + c.RangeEnd, + } +} + +func (m *loggableValueCompare) Reset() { *m = loggableValueCompare{} } +func (m *loggableValueCompare) String() string { return proto.CompactTextString(m) } +func (*loggableValueCompare) ProtoMessage() {} + +// loggablePutRequest implements a custom proto String to replace value bytes field with a value +// 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"` +} + +func newLoggablePutRequest(request *PutRequest) *loggablePutRequest { + return &loggablePutRequest{ + request.Key, + len(request.Value), + request.Lease, + request.PrevKv, + request.IgnoreValue, + request.IgnoreLease, + } +} + +func (m *loggablePutRequest) Reset() { *m = loggablePutRequest{} } +func (m *loggablePutRequest) String() string { return proto.CompactTextString(m) } +func (*loggablePutRequest) ProtoMessage() {} From 4db8b94cca6b49a9b11059921b05424a8f6336b5 Mon Sep 17 00:00:00 2001 From: Joe Betz Date: Thu, 7 Jun 2018 22:44:46 -0700 Subject: [PATCH 5/6] 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 | 4 -- etcdserver/util.go | 51 ++++++++++++++++--- etcdserver/v3_server.go | 19 ++++--- 5 files changed, 62 insertions(+), 23 deletions(-) diff --git a/etcdserver/apply.go b/etcdserver/apply.go index 220366ea822..3971fdf608f 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -88,9 +88,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 57e4b8f2e30..67f30a0bb81 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 de9057a0937..f1fcfd88087 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, } } diff --git a/etcdserver/util.go b/etcdserver/util.go index f1ba2dbecf4..f07c4f22575 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 1bd528511fb..a5c1ece8aee 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -26,8 +26,6 @@ import ( "github.com/coreos/etcd/lease/leasehttp" "github.com/coreos/etcd/mvcc" "github.com/coreos/etcd/raft" - "github.com/gogo/protobuf/proto" - "github.com/gogo/protobuf/proto" "golang.org/x/net/context" ) @@ -82,23 +80,26 @@ type Authenticator interface { } func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeResponse, error) { - 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(nil, r) } if serr := s.doSerialize(ctx, chk, get); serr != nil { - return nil, serr + err = serr + return nil, err } return resp, err } @@ -133,7 +134,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 { From 0ce2ef14a15772474ed0fe34a4017588d1a23473 Mon Sep 17 00:00:00 2001 From: Joe Betz Date: Mon, 11 Jun 2018 16:58:48 -0700 Subject: [PATCH 6/6] etcdserver: Fix txn request 'took too long' warnings to use loggable request stringer --- etcdserver/etcdserverpb/raft_internal_stringer.go | 4 ++-- etcdserver/util.go | 3 ++- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/etcdserver/etcdserverpb/raft_internal_stringer.go b/etcdserver/etcdserverpb/raft_internal_stringer.go index f1fcfd88087..362b252cade 100644 --- a/etcdserver/etcdserverpb/raft_internal_stringer.go +++ b/etcdserver/etcdserverpb/raft_internal_stringer.go @@ -64,7 +64,7 @@ func (as *InternalRaftStringer) String() string { case as.Request.Txn != nil: return fmt.Sprintf("header:<%s> txn:<%s>", as.Request.Header.String(), - newLoggableTxnRequest(as.Request.Txn).String(), + NewLoggableTxnRequest(as.Request.Txn).String(), ) default: // nothing to redact @@ -78,7 +78,7 @@ type txnRequestStringer struct { Request *TxnRequest } -func newLoggableTxnRequest(request *TxnRequest) *txnRequestStringer { +func NewLoggableTxnRequest(request *TxnRequest) *txnRequestStringer { return &txnRequestStringer{request} } diff --git a/etcdserver/util.go b/etcdserver/util.go index f07c4f22575..708fee4cb60 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -109,7 +109,8 @@ func warnOfExpensiveRequest(now time.Time, reqStringer fmt.Stringer, respMsg pro warnOfExpensiveGenericRequest(now, reqStringer, "", resp, err) } -func warnOfExpensiveReadOnlyTxnRequest(now time.Time, reqStringer fmt.Stringer, txnResponse *pb.TxnResponse, err error) { +func warnOfExpensiveReadOnlyTxnRequest(now time.Time, r *pb.TxnRequest, txnResponse *pb.TxnResponse, err error) { + reqStringer := pb.NewLoggableTxnRequest(r) var resp string if !isNil(txnResponse) { var resps []string