Add tracing in etcd server to range, put and compact requests #11179

YoyinZyc · 2019-09-24T20:34:31Z

Fix issue #11166.
This pr creates a standalone trace pkg for record the lifecycle of the request in etcd server. We only enable tracing for range request in this pr. Please refer to issue #11166 for the motivation of it.

Here is the example output of range request with no threshold:

{"level":"info","ts":"2019-09-25T11:10:35.671-0700","caller":"traceutil/trace.go:116","msg":"trace[1475838163] range","detail":"{range_begin:foo; range_end:fooo; response_count:100000; response_revision:191496;}","duration":"131.11503ms","start":"2019-09-25T11:10:35.540-0700","end":"2019-09-25T11:10:35.671-0700","steps":["trace[1475838163] step 'agreement among raft nodes before linearized reading' (duration: 56.363µs)","trace[1475838163] step 'authentication' (duration: 7.283µs)","trace[1475838163] step 'range keys from in-memory index tree' (duration: 10.166116ms)","trace[1475838163] step 'range keys from bolt db' (duration: 91.280638ms)","trace[1475838163] step 'filter and sort the key-value pairs' (duration: 22.58693ms)","trace[1475838163] step 'assemble the response' (duration: 241.774µs)"]}

To avoid log flood, we choose to log out only when exceed the threshold. In this pr, we set the default threshold to 100ms which is as same as warnApplyDuration. Here is the example output with threshold:

{"level":"info","ts":"2019-09-25T09:59:32.744-0700","caller":"traceutil/trace.go:116","msg":"trace[633331442] range","detail":"{range_begin:foo; range_end:fooo; response_count:100000; response_revision:191496;}","duration":"132.449773ms","start":"2019-09-25T09:59:32.611-0700","end":"2019-09-25T09:59:32.744-0700","steps":["trace[633331442] step 'range keys from bolt db' (duration: 92.521911ms)","trace[633331442] step 'filter and sort the key-value pairs' (duration: 22.789099ms)"]}

Some steps disappear because the duration of these steps are smaller than stepThreshold which is threshold / (len(steps)+1).

As for performance, there is no obvious difference with and without trace when I run the benchmark with a range request of key count 100000.

jingyih · 2019-09-24T22:37:01Z

Thanks @YoyinZyc. For completeness, could you also share the benchmark result?

pkg/traceutil/trace.go

YoyinZyc · 2019-09-24T23:16:40Z

Here is the benchmark results.
I ran range request to get 100001 key's value which will trigger trace logging.
Without Trace:

With Trace:

As for small range request which will not exceed the trace logging threshold, I ran request to get 100 key's value.
Without Trace:

With Trace

pkg/traceutil/trace.go

gyuho · 2019-09-25T18:09:12Z

@YoyinZyc Can you provide example tracing log outputs with new changes?

YoyinZyc · 2019-09-25T18:16:06Z

@gyuho The example of new tracing log outputs were updated in my first comment.

jingyih · 2019-09-25T20:13:55Z

Can you also benchmark with short range requests to make sure there is no noticeable impact on throughput?

YoyinZyc · 2019-09-25T20:22:56Z

@jingyih The benchmark result for short range requests were updated in my benchmark comment above.

jingyih · 2019-09-26T18:08:21Z

Looks good. This PR makes breaking change to the following APIs which are not user facing. I think it is fine.

etcd/etcdserver/apply.go

Line 55 in 59fd194

    
           Range(ctx context.Context, txn mvcc.TxnRead, r *pb.RangeRequest) (*pb.RangeResponse, error)

etcd/mvcc/kv.go

Line 106 in 59fd194

Read(trace *traceutil.Trace) TxnRead

@gyuho @xiang90 Any concern?

pkg/traceutil/trace_test.go

mvcc/kvstore_txn.go

pkg/traceutil/trace.go

gyuho · 2019-09-26T18:30:30Z

Overall approach looks good, and consistent with kubernetes tracing. /cc @xiang90 @jpbetz

jpbetz · 2019-09-26T20:02:09Z

Looks great @YoyinZyc! I pre-reviewed this so I'll let the other maintainers weigh in, but LGTM.

@jingyih I see what you were saying about the sort and filter being relatively expensive. In the above example it takes 22.58693ms! This data is going to be super useful.

cc @wojtek-t

jingyih · 2019-09-26T20:22:25Z

@jingyih I see what you were saying about the sort and filter being relatively expensive. In the above example it takes 22.58693ms! This data is going to be super useful.

Potentially, the step "Range keys from in-memory index tree" could also be relatively expensive if client is listing a lot of keys in pages. (e.g. listing 1 million events in 500-sized pages).

wojtek-t · 2019-09-27T06:23:57Z

@mborsz @mm4tt - FYI (it will be super useful for us)

@jingyih @jpbetz - is that something we may consider patching to 3.4 etcd? It seems like extremely useful thing for debugging both tests and production

gyuho · 2019-09-28T06:43:12Z

Yeah, let's try to merge and release in v3.4.2 next week. I will take another look next week.

pkg/traceutil/trace.go

gyuho

Some minor clean up, overall looks great!

@YoyinZyc Can we squash commits? We need cherry-pick this to 3.4, and squashing commits would make it easier.

pkg/traceutil/trace.go

pkg/traceutil/trace_test.go

etcdserver/v3_server.go

pkg/traceutil/trace.go

xiang90 · 2019-09-30T17:49:49Z

do we have plan to add tracing to other operations?

steps:range from the in-memory index tree; range from boltdb. etcdserver: add tracing steps: agreement among raft nodes before linerized reading; authentication; filter and sort kv pairs; assemble the response.

to reduce log volume.

gyuho · 2019-09-30T20:22:33Z

do we have plan to add tracing to other operations?

Any other use case @jpbetz @jingyih?

Since we are backporting this to v3.4, it would be better if we add them all at once.

jingyih · 2019-09-30T20:48:02Z

Giving that K8s uses Range and Txn heavily, I think it makes sense to also add tracing for Txn.

xiang90 · 2019-09-30T21:34:53Z

I guess we should add tracing to all operations to make it more consistent inside etcd.

YoyinZyc · 2019-10-01T00:43:11Z

I think it makes sense to add tracing to kv operations. I will put them into another pr. Btw, I opened an issue #11191 on txn tracing.

wojtek-t · 2019-10-01T06:10:54Z

If we would like to cherrypick it to 3.4 release (which in my opinion would be highly valuable), I think we should try to do everything we want in a single PR to avoid cherrypicking a number of PRs.

gyuho · 2019-10-01T16:53:45Z

@YoyinZyc Let's trace Write and Compaction in this PR, with additional commits. For first iteration, I think we are fine with same approach for Txn as well (just pass context to read and write transaction inside txn)?

mvcc: add put request steps; add trace to KV.Write() as input parameter.

YoyinZyc · 2019-10-02T00:24:00Z

Added trace to put and compaction.
Here are the example outputs:
Put:

"level":"info","ts":"2019-10-01T17:15:44.362-0700","caller":"traceutil/trace.go:137","msg":"trace[1967314171] put","detail":"{key:foo; value:prev; }","duration":"316.876µs","start":"2019-10-01T17:15:44.362-0700","end":"2019-10-01T17:15:44.362-0700","steps":["trace[1967314171] 'process raft request' (duration: 165.181µs)","trace[1967314171] 'get previous kv pair' (duration: 37.337µs)","trace[1967314171] 'get key's previous created_revision and leaseID' (duration: 3.716µs)","trace[1967314171] 'marshal mvccpb.KeyValue' (duration: 2.749µs)","trace[1967314171] 'store kv pair into bolt db' (duration: 38.504µs)","trace[1967314171] 'attach lease to kv pair' (duration: 198ns)"]}

Compaction:

{"level":"info","ts":"2019-10-01T17:17:11.971-0700","caller":"traceutil/trace.go:137","msg":"trace[672567340] compact","detail":"{revision:25000; }","duration":"277.299646ms","start":"2019-10-01T17:17:11.694-0700","end":"2019-10-01T17:17:11.971-0700","steps":["trace[672567340] 'process raft request' (duration: 120.154µs)","trace[672567340] 'check and update compact revision' (duration: 9.448069ms)","trace[672567340] 'compact in-memory index tree' (duration: 8.871586ms)","trace[672567340] 'schedule compaction' (duration: 15.347µs)","trace[672567340] 'physically apply compaction' (duration: 258.812035ms)"]}

gyuho · 2019-10-03T17:33:52Z

etcdserver/apply.go

-	Put(txn mvcc.TxnWrite, p *pb.PutRequest) (*pb.PutResponse, error)
-	Range(txn mvcc.TxnRead, r *pb.RangeRequest) (*pb.RangeResponse, error)
+	Put(txn mvcc.TxnWrite, p *pb.PutRequest) (*pb.PutResponse, *traceutil.Trace, error)
+	Range(ctx context.Context, txn mvcc.TxnRead, r *pb.RangeRequest) (*pb.RangeResponse, error)


Can we make method signatures consistent for Put and Compaction?

For me, passing context.Context seems cleaner.

It is hard to make it consistent with range. For put and compaction request, they need to make raft request first. When etcdserver receives the signal from raft, it will trigger the following apply process.

etcd/etcdserver/v3_server.go

Line 113 in c2f2309

resp, err := s.raftRequest(ctx, pb.InternalRaftRequest{Put: r})

etcd/etcdserver/server.go

Line 1036 in c2f2309

case ap := <-s.r.apply():

I don't think it is a good way to change too many apis inside raft. Therefore, the way I use now is to trace in apply then measure the raft request time by calculate the time difference between apply start time and req start time
Do you think it makes sense?

Ok, makes sense.

Btw, we don't really need ctx parameter to Range unless we want to trace more in auth applier? Can we just create trace object at the top level of Range method?

Oh, wait. It has to be passed from v3 server. So, nvm.

gyuho

lgtm, thanks for the great work.

Defer to @xiang90 @jingyih @jpbetz for final review.

jingyih

Thanks @YoyinZyc! Overall looks good!

etcdserver/apply.go

etcdserver/v3_server.go

pkg/traceutil/trace.go

etcdserver/v3_server.go

pkg/traceutil/trace.go

etcdserver/v3_server.go

jingyih

Added one comment. LGTM otherwise.

pkg/traceutil/trace.go

… applierV3.Compaction() mvcc: trace compaction request; add input parameter 'trace' to KV.Compact()

jingyih · 2019-10-08T18:07:09Z

LGTM

gyuho · 2019-10-08T20:24:29Z

@YoyinZyc Please highlight this in our CHANGELOG. And can you work on backporting this to v3.4 branch?

CHANGELOG: update #11179 in changelog-3.4

…79-origin-release-3.4 Automated cherry pick of #11179

YoyinZyc force-pushed the trace branch from 4066a9a to 7f58e0c Compare September 24, 2019 22:29

gyuho reviewed Sep 24, 2019

View reviewed changes

pkg/traceutil/trace.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 24, 2019

View reviewed changes

pkg/traceutil/trace.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 25, 2019

View reviewed changes

pkg/traceutil/trace.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 26, 2019

View reviewed changes

pkg/traceutil/trace_test.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 26, 2019

View reviewed changes

mvcc/kvstore_txn.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 26, 2019

View reviewed changes

pkg/traceutil/trace.go Outdated Show resolved Hide resolved

gyuho reviewed Sep 26, 2019

View reviewed changes

pkg/traceutil/trace.go Show resolved Hide resolved

YoyinZyc requested a review from gyuho September 26, 2019 21:04

gyuho reviewed Sep 30, 2019

View reviewed changes

pkg/traceutil/trace.go Show resolved Hide resolved

gyuho suggested changes Sep 30, 2019

View reviewed changes

YoyinZyc added 3 commits September 30, 2019 13:06

pkg: create package traceutil for tracing. mvcc: add tracing

f4e7fc5

steps:range from the in-memory index tree; range from boltdb. etcdserver: add tracing steps: agreement among raft nodes before linerized reading; authentication; filter and sort kv pairs; assemble the response.

pkg: add field to record additional detail of trace; add stepThreshold

3830b3e

to reduce log volume.

pkg: use zap logger to format the structure log output.

1d6ef83

YoyinZyc force-pushed the trace branch from 79a7a0d to 1d6ef83 Compare September 30, 2019 20:18

YoyinZyc requested a review from gyuho October 1, 2019 16:41

YoyinZyc added 2 commits October 1, 2019 14:08

etcdserver: add put request steps.

401df4b

mvcc: add put request steps; add trace to KV.Write() as input parameter.

etcdserver: trace raft requests.

3a3eb24

gyuho reviewed Oct 3, 2019

View reviewed changes

gyuho added backport/v3.4 type/feature labels Oct 3, 2019

gyuho added this to the etcd-v3.5 milestone Oct 3, 2019

gyuho approved these changes Oct 3, 2019

View reviewed changes

jingyih reviewed Oct 4, 2019

View reviewed changes

YoyinZyc force-pushed the trace branch from 4b7ed9a to 0775934 Compare October 4, 2019 19:49

jingyih reviewed Oct 5, 2019

View reviewed changes

pkg/traceutil/trace.go Outdated Show resolved Hide resolved

etcdserver: trace compaction request; add return parameter 'trace' to…

57aa68a

… applierV3.Compaction() mvcc: trace compaction request; add input parameter 'trace' to KV.Compact()

YoyinZyc force-pushed the trace branch from 0775934 to 57aa68a Compare October 7, 2019 16:59

gyuho merged commit 340f0ac into etcd-io:master Oct 8, 2019

YoyinZyc mentioned this pull request Oct 9, 2019

Automated cherry pick of #11179 #11223

Merged

YoyinZyc changed the title ~~Add tracing to range request in etcd server.~~ Add tracing to range, put, compact request in etcd server. Oct 9, 2019

YoyinZyc changed the title ~~Add tracing to range, put, compact request in etcd server.~~ Add tracing in etcd server to range, put and compact requests Oct 9, 2019

YoyinZyc added a commit to YoyinZyc/etcd that referenced this pull request Oct 9, 2019

CHANGELOG: update etcd-io#11179 in changelog-3.4

fe2ada4

gyuho added a commit that referenced this pull request Oct 9, 2019

Merge pull request #11224 from YoyinZyc/update-changelog

a6a1fdd

CHANGELOG: update #11179 in changelog-3.4

gyuho added a commit that referenced this pull request Oct 9, 2019

Merge pull request #11223 from YoyinZyc/automated-cherry-pick-of-#111…

2c36cab

…79-origin-release-3.4 Automated cherry pick of #11179

jingyih mentioned this pull request Oct 25, 2019

mvcc/kvstore: Optimize compaction #11150

Closed

YoyinZyc mentioned this pull request Dec 13, 2019

Connect lower level traces to surrounding request handling trace kubernetes/kubernetes#79209

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add tracing in etcd server to range, put and compact requests #11179

Add tracing in etcd server to range, put and compact requests #11179

YoyinZyc commented Sep 24, 2019 •

edited

Loading

jingyih commented Sep 24, 2019

YoyinZyc commented Sep 24, 2019 •

edited

Loading

gyuho commented Sep 25, 2019

YoyinZyc commented Sep 25, 2019

jingyih commented Sep 25, 2019

YoyinZyc commented Sep 25, 2019

jingyih commented Sep 26, 2019

gyuho commented Sep 26, 2019

jpbetz commented Sep 26, 2019

jingyih commented Sep 26, 2019 •

edited

Loading

wojtek-t commented Sep 27, 2019

gyuho commented Sep 28, 2019

gyuho left a comment

xiang90 commented Sep 30, 2019

gyuho commented Sep 30, 2019

jingyih commented Sep 30, 2019

xiang90 commented Sep 30, 2019

YoyinZyc commented Oct 1, 2019

wojtek-t commented Oct 1, 2019

gyuho commented Oct 1, 2019

YoyinZyc commented Oct 2, 2019

gyuho Oct 3, 2019

YoyinZyc Oct 3, 2019

gyuho Oct 3, 2019

gyuho Oct 3, 2019

gyuho left a comment

jingyih left a comment

jingyih left a comment

jingyih commented Oct 8, 2019

gyuho commented Oct 8, 2019

Add tracing in etcd server to range, put and compact requests #11179

Add tracing in etcd server to range, put and compact requests #11179

Conversation

YoyinZyc commented Sep 24, 2019 • edited Loading

jingyih commented Sep 24, 2019

YoyinZyc commented Sep 24, 2019 • edited Loading

gyuho commented Sep 25, 2019

YoyinZyc commented Sep 25, 2019

jingyih commented Sep 25, 2019

YoyinZyc commented Sep 25, 2019

jingyih commented Sep 26, 2019

gyuho commented Sep 26, 2019

jpbetz commented Sep 26, 2019

jingyih commented Sep 26, 2019 • edited Loading

wojtek-t commented Sep 27, 2019

gyuho commented Sep 28, 2019

gyuho left a comment

Choose a reason for hiding this comment

xiang90 commented Sep 30, 2019

gyuho commented Sep 30, 2019

jingyih commented Sep 30, 2019

xiang90 commented Sep 30, 2019

YoyinZyc commented Oct 1, 2019

wojtek-t commented Oct 1, 2019

gyuho commented Oct 1, 2019

YoyinZyc commented Oct 2, 2019

gyuho Oct 3, 2019

Choose a reason for hiding this comment

YoyinZyc Oct 3, 2019

Choose a reason for hiding this comment

gyuho Oct 3, 2019

Choose a reason for hiding this comment

gyuho Oct 3, 2019

Choose a reason for hiding this comment

gyuho left a comment

Choose a reason for hiding this comment

jingyih left a comment

Choose a reason for hiding this comment

jingyih left a comment

Choose a reason for hiding this comment

jingyih commented Oct 8, 2019

gyuho commented Oct 8, 2019

YoyinZyc commented Sep 24, 2019 •

edited

Loading

YoyinZyc commented Sep 24, 2019 •

edited

Loading

jingyih commented Sep 26, 2019 •

edited

Loading