etcdserver: Add response byte size and range response count to took too long warning #9826

jpbetz · 2018-06-08T17:12:37Z

Large range reads can result in "took too long" warnings. This adds range response counts as well as total proto response message size (in bytes) to the warnings to help debug situations where knowing the volume of data returned can help diagnose an issue.

put:

BEFORE:
2018-06-08 10:11:40.140673 W | etcdserver: read-only range request "key:\"/a\" range_end:\"/b\" " took too long (97.966µs) to execute

AFTER:
2018-06-08 10:11:40.140673 W | etcdserver: read-only range request "key:\"/a\" range_end:\"/b\" " with result "range_response_count:3 size:96" took too long (97.966µs) to execute

txn:

BEFORE:
etcdserver: read-only range request "compare:<target:VALUE key:\"a\" value:\"1\" > success:<request_range:<key:\"/a\" range_end:\"/b\" > > failure:<request_range:<key:\"/a\" range_end:\"/b\" > > " took too long (68.588µs) to execute

AFTER:
etcdserver: read-only range request "compare:<target:VALUE key:\"a\" value:\"1\" > success:<request_range:<key:\"/a\" range_end:\"/b\" > > failure:<request_range:<key:\"/a\" range_end:\"/b\" > > " with result "responses:<<range_response_count:3>> size:104" took too long (68.588µs) to execute

cc @gyuho @wenjiaswe @mml

jpbetz · 2018-06-08T17:36:31Z

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)


Is v3 only acceptable?

*RequestV2 also satisfies proto.Message interface, but I don't mind just passing nil for v2 API (since this is a new feature, no need to worry about v2 behavior).

gyuho

lgtm thanks!

gyuho · 2018-06-08T18:00:02Z

Marking as WIP until we figure out CI failures.

jpbetz · 2018-06-08T18:28:29Z

Reviewing a problem with proto.Size from integration tests:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0xa90726]

github.com/coreos/etcd/etcdserver/etcdserverpb.(*PutResponse).Size(0x0, 0x4cac5b)
        /usr/local/google/home/jpbetz/Projects/etcd/src/github.com/coreos/etcd/etcdserver/etcdserverpb/rpc.pb.go:8148 +0x26
github.com/coreos/etcd/etcdserver/etcdserverpb.(*PutResponse).Marshal(0x0, 0x176af60, 0x0, 0x7fbfb4a53af0, 0x0, 0x1)
        /usr/local/google/home/jpbetz/Projects/etcd/src/github.com/coreos/etcd/etcdserver/etcdserverpb/rpc.pb.go:5161 +0x2f
github.com/coreos/etcd/vendor/github.com/golang/protobuf/proto.Size(0x176af60, 0x0, 0xc420117880)
        /usr/local/google/home/jpbetz/Projects/etcd/src/github.com/coreos/etcd/vendor/github.com/golang/protobuf/proto/table_marshal.go:2602 +0x100
github.com/coreos/etcd/etcdserver.warnOfExpensiveRequest(0xc428750060, 0xbebecd857a50c3e6, 0xdde501b3a, 0x17c4620, 0x17604e0, 0xc4203a88c0, 0x176af60, 0x0, 0x175f920, 0xc42014db10)

https://github.com/coreos/etcd/blob/c6e18c712c7cc336a86404478297afa6063a72eb/etcdserver/etcdserverpb/rpc.pb.go#L8148

https://github.com/coreos/etcd/blob/c6e18c712c7cc336a86404478297afa6063a72eb/etcdserver/etcdserverpb/rpc.pb.go#L5161

It appears that somehow Marshal is called on a nil pointer here:

https://github.com/golang/protobuf/blob/b4deda0973fb4c70b50d226b1af49f3da59f5265/proto/table_marshal.go#L2602

gyuho · 2018-06-08T19:55:05Z

ref. golang/protobuf#631

Also, later we can replace https://github.com/coreos/etcd/blob/61ef343166eabab25deebf4e83b6e647aa4402fe/etcdserver/quota.go#L126-L137 with proto.Size.

jpbetz · 2018-06-08T19:56:52Z

I've put a workaround for the proto.Size panic. I'm not thrilled with it, but it still gives us more data than we had before.

Integration tests are now passing. I'll wait for CI.

gyuho · 2018-06-08T20:33:01Z

etcdserver/util.go

+		if r := recover(); r != nil {
+			size = "proto_size_failure"
+		}
+	}()


Would this work?

import "github.com/golang/protobuf/proto" ms, ok := msg.(proto.Marshaler) if ms == nil || !ok { return "proto_size_failure" }

Unfortunately no, I just tried it and got the same error.

I see. Then, let's use recover for now, and revert it back to upstream proto.Size later.

Sounds good. Too bad we can't have a clean PR for this improvement. I'll track the upstream issue and propose a PR if needed.

jpbetz · 2018-06-08T22:00:49Z

Just waiting on a clean semaphoreci run now.

gyuho · 2018-06-08T23:26:59Z

@jpbetz I noticed that proto.Message can be non-nil even if the original typed object was nil.

In TestCtlV3Compact, we are passing *etcdserverpb.CompactionResponse nil object as proto.Message interface, but once it's converted to proto.Message, the interface proto.Message itself is not nil since the original object still points to something.

 // safeSize attempt to calculate size using proto.Size, but recovers from panics and returns "proto_size_failure" in those cases.
 // TODO: Remove once https://github.com/golang/protobuf/issues/631 is resolved.
 func safeSize(msg proto.Message) (size string) {
+       fmt.Println("safeSize:", msg == nil, reflect.ValueOf(msg).IsNil())

This will print out safeSize: false true.

So, it will panic in proto.Marshaler.Marshal.

func (m *CompactionResponse) Marshal() (dAtA []byte, err error) {
	size := m.Size()

jpbetz · 2018-06-08T23:36:31Z

@gyuho Thanks for hunting this down. I'd been warned before of this gotcha with interfaces! Fixing now.

wenjiaswe · 2018-06-09T00:16:16Z

Very useful information. LGTM.

jpbetz · 2018-06-09T04:51:54Z

proto.Size calls were indeed fixed by checking for non-nil proto.Message interfaces with nil value pointers per @gyuho's suggestion. Also fixed a mistake in how the error handling code in Range was rearranged to instrument measuring response sizes. Once tests are green this is ready for merge.

gyuho · 2018-06-11T16:49:12Z

etcdserver/util.go

+func warnOfExpensiveRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, respMsg proto.Message, err error) {
+	var resp string
+	if !isNil(respMsg) {
+		resp = fmt.Sprintf("size:%s", proto.Size(respMsg))


Yes, thanks. The safeSize function I used before returned a string. Fixing.

gyuho · 2018-06-11T16:49:29Z

etcdserver/util.go

+func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, 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:%s", len(rangeResponse.Kvs), proto.Size(rangeResponse))


"range_response_count:%d size:%d"?

gyuho · 2018-06-11T16:50:05Z

etcdserver/util.go

+				// only range responses should be in a read only txn request
+			}
+		}
+		resp = fmt.Sprintf("responses:<%s> size:%s", strings.Join(resps, " "), proto.Size(txnResponse))


"responses:<%s> size:%d"?

…oo long warning

gyuho

lgtm thanks!

jpbetz added the Release-Backport/v3.2 label Jun 8, 2018

jpbetz force-pushed the response_sizes branch from cdbcff4 to 794aa99 Compare June 8, 2018 17:33

jpbetz commented Jun 8, 2018

View reviewed changes

gyuho approved these changes Jun 8, 2018

View reviewed changes

gyuho added the WIP label Jun 8, 2018

jpbetz force-pushed the response_sizes branch from 794aa99 to 50e9b03 Compare June 8, 2018 19:43

jpbetz force-pushed the response_sizes branch from 50e9b03 to 63ba88d Compare June 8, 2018 19:55

gyuho reviewed Jun 8, 2018

View reviewed changes

gyuho approved these changes Jun 8, 2018

View reviewed changes

gyuho removed the WIP label Jun 8, 2018

jpbetz force-pushed the response_sizes branch 2 times, most recently from adf989f to df47105 Compare June 9, 2018 04:46

gyuho reviewed Jun 11, 2018

View reviewed changes

etcdserver: Add response byte size and range response count to took t…

b47e148

…oo long warning

jpbetz force-pushed the response_sizes branch from df47105 to b47e148 Compare June 11, 2018 17:02

gyuho approved these changes Jun 11, 2018

View reviewed changes

gyuho merged commit 849d3f2 into etcd-io:master Jun 11, 2018

jpbetz mentioned this pull request Jun 11, 2018

Automated cherry pick of detailed "took too long" warnings to release-3.2 #9821

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

etcdserver: Add response byte size and range response count to took too long warning #9826

etcdserver: Add response byte size and range response count to took too long warning #9826

jpbetz commented Jun 8, 2018 •

edited

Loading

jpbetz Jun 8, 2018

gyuho Jun 8, 2018

gyuho left a comment

gyuho commented Jun 8, 2018

jpbetz commented Jun 8, 2018 •

edited

Loading

gyuho commented Jun 8, 2018

jpbetz commented Jun 8, 2018

gyuho Jun 8, 2018

jpbetz Jun 8, 2018

gyuho Jun 8, 2018

jpbetz Jun 8, 2018

jpbetz commented Jun 8, 2018

gyuho commented Jun 8, 2018 •

edited

Loading

jpbetz commented Jun 8, 2018

wenjiaswe commented Jun 9, 2018

jpbetz commented Jun 9, 2018 •

edited

Loading

gyuho Jun 11, 2018

jpbetz Jun 11, 2018

gyuho Jun 11, 2018

jpbetz Jun 11, 2018

gyuho Jun 11, 2018

jpbetz Jun 11, 2018

gyuho left a comment

etcdserver: Add response byte size and range response count to took too long warning #9826

etcdserver: Add response byte size and range response count to took too long warning #9826

Conversation

jpbetz commented Jun 8, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gyuho left a comment

Choose a reason for hiding this comment

gyuho commented Jun 8, 2018

jpbetz commented Jun 8, 2018 • edited Loading

gyuho commented Jun 8, 2018

jpbetz commented Jun 8, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jpbetz commented Jun 8, 2018

gyuho commented Jun 8, 2018 • edited Loading

jpbetz commented Jun 8, 2018

wenjiaswe commented Jun 9, 2018

jpbetz commented Jun 9, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gyuho left a comment

Choose a reason for hiding this comment

jpbetz commented Jun 8, 2018 •

edited

Loading

jpbetz commented Jun 8, 2018 •

edited

Loading

gyuho commented Jun 8, 2018 •

edited

Loading

jpbetz commented Jun 9, 2018 •

edited

Loading