tracing,sql: introduce BenchmarkTracing #58712

irfansharif · 2021-01-11T17:16:21Z

BenchmarkTracing measures the overhead of always-on tracing. It also
reports the memory utilization.

make bench PKG=./pkg/bench \
  TESTFLAGS='-benchtime=5000x -count 20' \
  BENCHES='BenchmarkTracing' BENCHTIMEOUT=50m

Plumbing that into benchstat (old is without always-on tracing, new is
with):

name                                            old time/op    new time/op    delta
Tracing/Cockroach/tracing=x/Scan1-16               172µs ± 2%     164µs ± 4%   -4.87%  (p=0.000 n=17+19)
Tracing/Cockroach/tracing=x/Insert-16              253µs ± 5%     249µs ± 5%   -1.68%  (p=0.028 n=19+20)
Tracing/MultinodeCockroach/tracing=x/Scan1-16      413µs ± 5%     491µs ±30%  +18.89%  (p=0.000 n=19+20)
Tracing/MultinodeCockroach/tracing=x/Insert-16     543µs ±12%     539µs ± 7%     ~     (p=0.925 n=20+20)

name                                            old alloc/op   new alloc/op   delta
Tracing/Cockroach/tracing=x/Scan1-16              23.0kB ± 0%    23.3kB ± 2%   +0.95%  (p=0.000 n=17+17)
Tracing/Cockroach/tracing=x/Insert-16             38.7kB ±21%    38.1kB ± 7%     ~     (p=0.687 n=20+19)
Tracing/MultinodeCockroach/tracing=x/Scan1-16     72.0kB ±15%    75.1kB ±10%   +4.28%  (p=0.000 n=19+20)
Tracing/MultinodeCockroach/tracing=x/Insert-16     102kB ±19%     101kB ±11%     ~     (p=0.813 n=20+19)

name                                            old allocs/op  new allocs/op  delta
Tracing/Cockroach/tracing=x/Scan1-16                 247 ± 0%       248 ± 1%   +0.21%  (p=0.004 n=16+17)
Tracing/Cockroach/tracing=x/Insert-16                309 ± 0%       310 ± 2%     ~     (p=0.059 n=17+20)
Tracing/MultinodeCockroach/tracing=x/Scan1-16        762 ± 3%       766 ± 3%   +0.58%  (p=0.015 n=17+19)
Tracing/MultinodeCockroach/tracing=x/Insert-16       734 ± 3%       733 ± 2%     ~     (p=0.402 n=19+19)

Release note: None

cockroach-teamcity · 2021-01-11T17:16:27Z

This change is

tbg · 2021-01-11T22:03:23Z

pkg/server/node.go

@@ -959,6 +959,7 @@ func (n *Node) setupSpanForIncomingRPC(
 		if br == nil {
 			return
 		}
+		// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


Because grpcSpan comes from Context, meaning that whoever put it there is in charge of finishing it.
For newSpan, we return finishSpan from this method.

Ah, thanks. Removed.

tbg · 2021-01-11T22:04:59Z

pkg/cli/start.go

@@ -330,8 +330,8 @@ func runStart(cmd *cobra.Command, args []string, startSingleNode bool) (returnEr
 	// has completed.
 	// TODO(andrei): we don't close the span on the early returns below.
 	tracer := serverCfg.Settings.Tracer
-	sp := tracer.StartSpan("server start")
-	ctx = tracing.ContextWithSpan(ctx, sp)
+	startupSpan := tracer.StartSpan("server start")


Why this rename? We call this sp everywhere else and there isn't anything special about this one (except that it's long-running).

I think it would be more useful to terminate this span when the server has fully started, and to make another span for the shutdown sequence, by the way. We should minimize spans that are basically always there as they'll just clutter up the registry and will have their events ultimately dropped anyway.

We're using shutdownSpan down below, which is why.

I think it would be more useful to terminate this span when the server has fully started, and to make another span for the shutdown sequence, by the way.

This already happens with shutdownSpan.

tbg · 2021-01-11T22:05:53Z

pkg/sql/colflow/vectorized_flow.go

@@ -947,6 +947,7 @@ func (s *vectorizedFlowCreator) setupOutput(
 						// Start a separate recording so that GetRecording will return
 						// the recordings for only the child spans containing stats.
 						ctx, span := tracing.ChildSpanRemote(ctx, "")
+						// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


This should be finished right away. This whole span will actually go away at some point. It's a workaround for the old SpanStats stuff before I updated it to support multiple entries per Span.

(by "right away" I mean after line 967)

tbg · 2021-01-11T22:07:33Z

pkg/sql/conn_executor_exec.go

@@ -636,6 +636,7 @@ func (ex *connExecutor) execStmtInOpenState(
 	if !alreadyRecording && stmtTraceThreshold > 0 {
 		ctx, stmtThresholdSpan = createRootOrChildSpan(ctx, "trace-stmt-threshold", ex.transitionCtx.tracer)
 		stmtThresholdSpan.SetVerbose(true)
+		// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


Yep, looks like this should be finished at the end of the block at line 646.

tbg · 2021-01-11T22:12:35Z

pkg/sql/tests/kv_test.go

+
+// BenchmarkTracing measures the overhead of always-on tracing. It also reports
+// the memory utilization.
+func BenchmarkTracing(b *testing.B) {


Will this run during make bench? If so, this is likely overkill. We don't care much about comparisons between the tracing modes once the default is flipped (since we have no intention of going back). If we want to keep the different modes around during the transition period that's fine by me, but you can just make a one-line addition of newKVSQLWithTracing here:

cockroach/pkg/sql/tests/kv_test.go

Line 273 in f54afe7

newKVSQL,

and then we don't have to duplicate the whole benchmark.

tbg · 2021-01-11T22:19:24Z

This benchmark is only doing single-node operations, which benefit from the local grpc optimization and which in turn elides the KV-side creation of spans. Try using

cockroach/pkg/bench/bench_test.go

Lines 378 to 389 in e9214f6

    
           for _, runFn := range []func(*testing.B, *sqlutils.SQLRunner, int){ 
        
           	runBenchmarkDelete, 
        
           	runBenchmarkInsert, 
        
           	runBenchmarkInsertDistinct, 
        
           	runBenchmarkInsertFK, 
        
           	runBenchmarkInsertSecondaryIndex, 
        
           	runBenchmarkInterleavedSelect, 
        
           	runBenchmarkInterleavedFK, 
        
           	runBenchmarkTrackChoices, 
        
           	runBenchmarkUpdate, 
        
           	runBenchmarkUpsert, 
        
           } {

which also exercises the multi-node case via ForEachDB, and in particular makes sure all gateways are used equally.

I think what I did when I played with the allocations was to make a BenchmarkSelectNone based off of

https://github.com/tbg/cockroach/blob/e9214f68130b6942990a04da197a1e514595b1df/pkg/bench/bench_test.go#L42-L45

(which is too simplistic b/c it doesn't hit KV at all) that point selected from an empty table. We should do the same for the simplest write workload possible (since writing creates different spans) to cover out bases, but I don't think there's too much of a need to cover larger read/write sets.

irfansharif

Repurposed to use multi-node clusters instead, PTAL. And yup, was imagining that we'd delete this benchmark once we're confident in always-on tracing (so early 21.2). Added a TODO to that effect.

irfansharif · 2021-01-11T22:30:16Z

pkg/cli/start.go

@@ -330,8 +330,8 @@ func runStart(cmd *cobra.Command, args []string, startSingleNode bool) (returnEr
 	// has completed.
 	// TODO(andrei): we don't close the span on the early returns below.
 	tracer := serverCfg.Settings.Tracer
-	sp := tracer.StartSpan("server start")
-	ctx = tracing.ContextWithSpan(ctx, sp)
+	startupSpan := tracer.StartSpan("server start")


We're using shutdownSpan down below, which is why.

I think it would be more useful to terminate this span when the server has fully started, and to make another span for the shutdown sequence, by the way.

This already happens with shutdownSpan.

irfansharif · 2021-01-11T22:32:16Z

pkg/server/node.go

@@ -959,6 +959,7 @@ func (n *Node) setupSpanForIncomingRPC(
 		if br == nil {
 			return
 		}
+		// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


Ah, thanks. Removed.

irfansharif · 2021-01-11T22:34:12Z

pkg/sql/colflow/vectorized_flow.go

@@ -947,6 +947,7 @@ func (s *vectorizedFlowCreator) setupOutput(
 						// Start a separate recording so that GetRecording will return
 						// the recordings for only the child spans containing stats.
 						ctx, span := tracing.ChildSpanRemote(ctx, "")
+						// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


irfansharif · 2021-01-11T22:34:52Z

pkg/sql/conn_executor_exec.go

@@ -636,6 +636,7 @@ func (ex *connExecutor) execStmtInOpenState(
 	if !alreadyRecording && stmtTraceThreshold > 0 {
 		ctx, stmtThresholdSpan = createRootOrChildSpan(ctx, "trace-stmt-threshold", ex.transitionCtx.tracer)
 		stmtThresholdSpan.SetVerbose(true)
+		// TODO(irfansharif): How come this span is never Finish()-ed? #58721.


tbg

Reviewed 6 of 6 files at r1, 1 of 2 files at r2, 5 of 5 files at r3.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @irfansharif and @knz)

pkg/sql/conn_executor_exec.go, line 639 at r2 (raw file):

Previously, irfansharif (irfan sharif) wrote…

Done.

Also needs to be finished on the early return between these two locations, unfortunately.

tbg · 2021-01-12T13:08:09Z

It looks like we now have BenchmarkTracing in two places, and that the one in kv_test.go should go away.

tbg · 2021-01-12T13:32:42Z

FWIW, I don't see the large change in Scan1:

tobias@td:~/go/src/github.com/cockroachdb/cockroach$ benchstat legacy.txt background.txt 
name                                           old time/op    new time/op    delta
Tracing/Cockroach/tracing=X/Scan1-16              196µs ± 2%     196µs ± 1%    ~     (p=0.690 n=5+5)
Tracing/MultinodeCockroach/tracing=X/Scan1-16     483µs ± 1%     478µs ± 1%    ~     (p=0.056 n=5+5)

name                                           old alloc/op   new alloc/op   delta
Tracing/Cockroach/tracing=X/Scan1-16             23.3kB ± 1%    23.4kB ± 1%    ~     (p=0.548 n=5+5)
Tracing/MultinodeCockroach/tracing=X/Scan1-16    73.1kB ± 1%    74.8kB ± 2%  +2.34%  (p=0.032 n=5+5)

name                                           old allocs/op  new allocs/op  delta
Tracing/Cockroach/tracing=X/Scan1-16                247 ± 0%       248 ± 1%    ~     (p=0.286 n=5+5)
Tracing/MultinodeCockroach/tracing=X/Scan1-16       762 ± 0%       767 ± 1%    ~     (p=0.333 n=5+5)

I ran

go test -benchtime 25000x -count 5 -bench BenchmarkTracing/Cockroach/tracing=/Scan1 ./pkg/bench/ | grep BenchmarkTracing | tee out

BenchmarkTracing measures the overhead of always-on tracing. It also reports the memory utilization. make bench PKG=./pkg/bench \ TESTFLAGS='-benchtime=5000x -count 20' \ BENCHES='BenchmarkTracing' BENCHTIMEOUT=50m Plumbing that into `benchstat` (old is without always-on tracing, new is with): name old time/op new time/op delta Tracing/Cockroach/tracing=x/Scan1-16 172µs ± 2% 164µs ± 4% -4.87% (p=0.000 n=17+19) Tracing/Cockroach/tracing=x/Insert-16 253µs ± 5% 249µs ± 5% -1.68% (p=0.028 n=19+20) Tracing/MultinodeCockroach/tracing=x/Scan1-16 413µs ± 5% 491µs ±30% +18.89% (p=0.000 n=19+20) Tracing/MultinodeCockroach/tracing=x/Insert-16 543µs ±12% 539µs ± 7% ~ (p=0.925 n=20+20) name old alloc/op new alloc/op delta Tracing/Cockroach/tracing=x/Scan1-16 23.0kB ± 0% 23.3kB ± 2% +0.95% (p=0.000 n=17+17) Tracing/Cockroach/tracing=x/Insert-16 38.7kB ±21% 38.1kB ± 7% ~ (p=0.687 n=20+19) Tracing/MultinodeCockroach/tracing=x/Scan1-16 72.0kB ±15% 75.1kB ±10% +4.28% (p=0.000 n=19+20) Tracing/MultinodeCockroach/tracing=x/Insert-16 102kB ±19% 101kB ±11% ~ (p=0.813 n=20+19) name old allocs/op new allocs/op delta Tracing/Cockroach/tracing=x/Scan1-16 247 ± 0% 248 ± 1% +0.21% (p=0.004 n=16+17) Tracing/Cockroach/tracing=x/Insert-16 309 ± 0% 310 ± 2% ~ (p=0.059 n=17+20) Tracing/MultinodeCockroach/tracing=x/Scan1-16 762 ± 3% 766 ± 3% +0.58% (p=0.015 n=17+19) Tracing/MultinodeCockroach/tracing=x/Insert-16 734 ± 3% 733 ± 2% ~ (p=0.402 n=19+19) Release note: None

irfansharif

The original recordings had a large stdev, would explain the discrepancy. I don't see the regression trying it out again:

$ benchstat old.txt new.txt
name                                           old time/op    new time/op    delta
Tracing/Cockroach/tracing=x/Scan1-16              161µs ± 1%     164µs ± 4%    ~     (p=0.068 n=8+10)
Tracing/MultinodeCockroach/tracing=x/Scan1-16     388µs ± 3%     380µs ± 4%    ~     (p=0.143 n=10+10)

name                                           old alloc/op   new alloc/op   delta
Tracing/Cockroach/tracing=x/Scan1-16             23.3kB ± 2%    23.4kB ± 2%    ~     (p=0.123 n=10+10)
Tracing/MultinodeCockroach/tracing=x/Scan1-16    71.7kB ± 1%    73.3kB ± 3%  +2.16%  (p=0.001 n=10+10)

name                                           old allocs/op  new allocs/op  delta
Tracing/Cockroach/tracing=x/Scan1-16                248 ± 1%       248 ± 0%    ~     (p=0.828 n=10+9)
Tracing/MultinodeCockroach/tracing=x/Scan1-16       760 ± 0%       761 ± 1%    ~     (p=0.153 n=10+8)

TFTR!

bors r+

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @knz and @tbg)

pkg/sql/conn_executor_exec.go, line 639 at r2 (raw file):

Previously, tbg (Tobias Grieger) wrote…

Also needs to be finished on the early return between these two locations, unfortunately.

Done.

craig · 2021-01-12T18:03:28Z

Build succeeded:

GitHub CI (Cockroach)

This is follow-up work from cockroachdb#58712, where we measured the overhead for always-on tracing and found it to be minimal/acceptable. Lets switch this on by default to shake the implications of doing so. We can reasonably expect two kinds of fallout: 1. Unexpected blow up in memory usage due to resource leakage (which is a can be problem now that we're always maintaining open spans in an internal registry, see cockroachdb#58721) 2. Performance degradataion due to tracing overhead per-request (something cockroachdb#58712) was spot checking for. For 1 we'll introduce a future test in a separate PR. For 2, we'll monitor roachperf over the next few weeks. --- Also moved some of the documentation for the cluster setting into a comment form above. Looking at what's rendered in our other cluster settings (`SHOW ALL CLUSTER SETTINGS`), we default to a very pity, unwrapped description. Release note: None

This is follow-up work from cockroachdb#58712, where we measured the overhead for always-on tracing and found it to be minimal/acceptable. Lets switch this on by default to shake the implications of doing so. We can reasonably expect two kinds of fallout: (1) Unexpected blow up in memory usage due to resource leakage (which is a can be problem now that we're always maintaining open spans in an internal registry, see cockroachdb#58721) (2) Performance degradataion due to tracing overhead per-request (something cockroachdb#58712) was spot checking for. For (1) we'll introduce a future test in a separate PR. For (2), we'll monitor roachperf over the next few weeks. --- Also moved some of the documentation for the cluster setting into a comment form above. Looking at what's rendered in our other cluster settings (`SHOW ALL CLUSTER SETTINGS`), we default to a very pithy, unwrapped description. Release note: None

58897: tracing: enable always-on tracing by default r=irfansharif a=irfansharif This is follow-up work from #58712, where we measured the overhead for always-on tracing and found it to be minimal/acceptable. Lets switch this on by default to shake the implications of doing so. We can reasonably expect two kinds of fallout: 1. Unexpected blow up in memory usage due to resource leakage (which is a can be problem now that we're always maintaining open spans in an internal registry, see #58721) 2. Performance degradataion due to tracing overhead per-request (something #58712) was spot checking for. For 1 we'll introduce a future test in a separate PR. For 2, we'll monitor roachperf over the next few weeks. --- Also moved some of the documentation for the cluster setting into a comment form above. Looking at what's rendered in our other cluster settings (`SHOW ALL CLUSTER SETTINGS`), we default to a very pity, unwrapped description. Release note: None 58974: opt: suppress logs in benchmarks r=rytaft a=mgartner As of #57134 passing `-logtostderr=false` as a `TESTFLAG` in benchmarks errs: `flag provided but not defined: -logtostderr`. The preferred method for suppressing logs in tests and benchmarks to is add `defer log.Scope(t).Close(t)` to the top of the test/benchmark (see #57979). This commit uses this new method to suppress logs in optimizer benchmarks. Release note: None 59009: kv/batcheval: only expose immutable range state to commands r=nvanbenschoten a=nvanbenschoten The DeclareKeysFunc has always included a full RangeDescriptor, but it has never been clear which fields in this descriptor are safe to use and which are not when declaring keys for a request. The concern is that any property of the RangeDescriptor that is not immutable may change between the time that a request declares its keys to latch and the time that it evaluates, so any assumptions based on these mutable fields may not hold. The quintessential example of a property of a Range that is not immutable is its end key. It would be incorrect to declare keys between a Range's start key and its current end key as a means of latching the entire range, because a merge of a right-hand neighbor could complete in between the time that a request declares its keys and the time that it evaluates. This could lead to a violation of the mutual exclusion that the command was expecting to have. This commit makes these kinds of mistakes impossible to make by putting the RangeDescriptor behind an interface that only exposes the properties of a Range that cannot change across a Range's lifetime. 59099: kvserver: fix rangelog event logging for non-voter additions r=aayushshah15 a=aayushshah15 Before this patch, we were incorrectly logging non-voter additions as removals. Release note: None 59142: sql: fix indentation in information_schema.columns schema r=otan a=arulajmani Reviewable lied to me. Release note: None Co-authored-by: irfan sharif <irfanmahmoudsharif@gmail.com> Co-authored-by: Marcus Gartner <marcus@cockroachlabs.com> Co-authored-by: Nathan VanBenschoten <nvanbenschoten@gmail.com> Co-authored-by: Aayush Shah <aayush.shah15@gmail.com> Co-authored-by: arulajmani <arulajmani@gmail.com>

irfansharif marked this pull request as draft January 11, 2021 17:16

tracing: miscellaneous cleanups

623063e

irfansharif force-pushed the 210111.tracing-overhead branch from 176ca75 to 8b6e272 Compare January 11, 2021 21:42

irfansharif marked this pull request as ready for review January 11, 2021 21:43

irfansharif requested a review from a team as a code owner January 11, 2021 21:43

irfansharif force-pushed the 210111.tracing-overhead branch from 8b6e272 to 87deb79 Compare January 11, 2021 21:43

irfansharif changed the title ~~[wip] tracing,sql: introduce BenchmarkTracing~~ tracing,sql: introduce BenchmarkTracing Jan 11, 2021

irfansharif requested review from tbg and knz and removed request for a team January 11, 2021 21:47

irfansharif force-pushed the 210111.tracing-overhead branch from 87deb79 to 4990d73 Compare January 11, 2021 21:47

tbg reviewed Jan 11, 2021

View reviewed changes

irfansharif force-pushed the 210111.tracing-overhead branch from 4990d73 to 36992b3 Compare January 12, 2021 00:30

irfansharif commented Jan 12, 2021

View reviewed changes

tbg approved these changes Jan 12, 2021

View reviewed changes

lunevalex added the A-tracing Relating to tracing in CockroachDB. label Jan 12, 2021

irfansharif force-pushed the 210111.tracing-overhead branch from 36992b3 to 513b01b Compare January 12, 2021 16:40

irfansharif commented Jan 12, 2021

View reviewed changes

craig bot merged commit d113ccb into cockroachdb:master Jan 12, 2021

irfansharif deleted the 210111.tracing-overhead branch January 12, 2021 18:05

irfansharif mentioned this pull request Jan 12, 2021

tracing: enable always-on tracing by default #58897

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tracing,sql: introduce BenchmarkTracing #58712

tracing,sql: introduce BenchmarkTracing #58712

irfansharif commented Jan 11, 2021 •

edited

Loading

cockroach-teamcity commented Jan 11, 2021

tbg Jan 11, 2021

irfansharif Jan 11, 2021

tbg Jan 11, 2021

irfansharif Jan 11, 2021

tbg Jan 11, 2021

tbg Jan 11, 2021

irfansharif Jan 11, 2021

tbg Jan 11, 2021

irfansharif Jan 11, 2021

tbg Jan 11, 2021

tbg commented Jan 11, 2021

irfansharif left a comment

irfansharif Jan 11, 2021

irfansharif Jan 11, 2021

irfansharif Jan 11, 2021

irfansharif Jan 11, 2021

tbg left a comment

tbg commented Jan 12, 2021

tbg commented Jan 12, 2021

irfansharif left a comment

craig bot commented Jan 12, 2021

tracing,sql: introduce BenchmarkTracing #58712

tracing,sql: introduce BenchmarkTracing #58712

Conversation

irfansharif commented Jan 11, 2021 • edited Loading

cockroach-teamcity commented Jan 11, 2021

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

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

tbg commented Jan 11, 2021

irfansharif left a 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

tbg left a comment

Choose a reason for hiding this comment

tbg commented Jan 12, 2021

tbg commented Jan 12, 2021

irfansharif left a comment

Choose a reason for hiding this comment

craig bot commented Jan 12, 2021

irfansharif commented Jan 11, 2021 •

edited

Loading