[dnm] tracing: investigate perf regression under sql.txn_stats.sample_rate=1

[tbg]

Old is sample_rate=0, new is sample_rate=1.

$ ./cmd.sh
name                                 old time/op  new time/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16   282µs ± 7%   336µs ± 9%  +18.97%  (p=0.000 n=10+10)

Touches #59379.

[cockroach-teamcity]

This change is 

[yuzefovich]

Reviewed 4 of 4 files at r8, 5 of 6 files at r9, 5 of 5 files at r10, 5 of 5 files at r11.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @tbg)

---

pkg/sql/instrumentation.go, line 181 at r11 (raw file):

			// If we need to collect stats, create a non-verbose child span. Stats
			// will be added as structured metadata and processed in Finish.
			sp := tracing.SpanFromContext(ctx)

This is not quite an equivalent change. In connExecutor.execCmd we create a span for every statement, so sp is always non-nil, but with the current change we tell instrumentationHelper to not "finish" which means that it will not process execution stats attached to the trace. I prototyped the proper usage of that already present span in yuzefovich@58ab90b, but it doesn't seem to change the micro benchmark numbers.

---

pkg/sql/colflow/stats.go, line 257 at r9 (raw file):

	// is not the way they are supposed to be used, so this should be fixed.
	if false {
		_, span := tracing.ChildSpan(ctx, opName)

After addressing the span creation in #61380, the performance gains of this commit in the benchmark went away. What this change essentially does is to drop on the floor all of the execution statistics we collected, thus there is less information to propagate via the trace.

[tbg]

Updated the PR on top of your recent work, @yuzefovich

@irfansharif as we discussed yesterday, mind taking a look here with me? The branch should be relatively clean now. I added a microbenchmark that tries to capture exactly the overhead that would be incurred from setting the sampling rate from zero to one. It incurs a cost, but I don't see anything that can explain the slow down I see via ./cmp.sh.

@yuzefovich could you scrutinize the microbenchmark? Is there any significant work that is done as a result of propagating component stats that it doesn't capture?

$ go test -run - -bench SpanStats -count 1 ./pkg/util/tracing
goos: linux
goarch: amd64
pkg: github.com/cockroachdb/cockroach/pkg/util/tracing
BenchmarkSpanStats/autoCollection=false,stats=0-16         	 280952	     4326 ns/op
BenchmarkSpanStats/autoCollection=false,stats=1-16         	 158040	     7901 ns/op

BenchmarkSpanStats/autoCollection=true,stats=0-16          	 471117	     2631 ns/op
BenchmarkSpanStats/autoCollection=true,stats=1-16          	 242348	     5919 ns/op
PASS
ok  	github.com/cockroachdb/cockroach/pkg/util/tracing	8.414s

The case autoCollection=false,stats=1 should roughly reflect the SQL
usage in which stats are created, transported via a recording, ingested
into a parent, and then retrieved and unmarshaled. The case false,stats=0
should correspond to the non-sampled case. We are thus expecting roughly
an overhead of 4.3µs/op when not sampled, 8µs/op when sampled, i.e.
changing the sampling rate from 0 to 1 should add ~4µs/op.
However, the macro-level benchmark shows much more:

KV/Scan/SQL/rows=1/sample_rate=X-16   268µs ± 9%   314µs ± 7%  +17.03%  (p=0.000 n=21+21)

That's a drop of 46µs incurred by changing the sampling rate from
zero to one, much past what can be explained by this microbenchmark.

The autoCollection=true numbers avoid an extra unmarshal-remarshal cycle
of the recording. This is a possible optimization for SQL to investigate
in the case in which the flow lives wholly on the gateway.
Unfortunately, it is finicky to get right and causes lots of special
casing, as SQL currently relies on all trace data arriving at the
DistSQL RowReceiver via TrailingMeta (i.e. marshalled recordings).

[tbg]

This is also consistent with this:

With RecordStructured turned into a noop:

name                                 old time/op  new time/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16   261µs ±10%   292µs ±10%  +12.08%  (p=0.000 n=20+21)
name                                 old time/op  new time/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16   267µs ±11%   293µs ± 6%  +9.40%  (p=0.000 n=21+21)

With RecordStructured doing its job:

name                                 old time/op  new time/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16   271µs ± 9%   310µs ± 8%  +14.69%  (p=0.000 n=21+21)
name                                 old time/op  new time/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16   276µs ± 7%   316µs ± 8%  +14.48%  (p=0.000 n=21+20)

If throwing away the ComponentStats offered to the Span, they won't get
marshalled or unmarshalled or even put on the wire. And yet, there's a 10%
performance hit for the setting. What is the expensive thing we're doing?
Creating more spans?

[tbg]

@yuzefovich I added span/op counts to the micro and SELECT benchmark I'm running. This shows that in ./cmp.sh benchmark, we're creating 8 spans when sampling, 7 when not sampling.

That one additional trace span is unlikely to cost ~40us, but avoiding
it would establish more parity between the tests. Can we do that, at least as a hack to see what the effect would be?

[tbg]

I tracked down the extra span, and it's this one:

cockroach/pkg/sql/colfetcher/colbatch_scan.go

Lines 92 to 96 in a9b582f

	if execinfra.ShouldCollectStats(s.ctx, s.flowCtx) {
	// We need to start a child span so that the only contention events
	// present in the recording would be because of this cFetcher.
	s.ctx, s.tracingSpan = execinfra.ProcessorSpan(s.ctx, "colbatchscan")
	}

I optimized it out 😎 but as expected it didn't make it or break it:

diff --git a/pkg/sql/colfetcher/colbatch_scan.go b/pkg/sql/colfetcher/colbatch_scan.go
index cae59582b8..6a69ff7f96 100644
--- a/pkg/sql/colfetcher/colbatch_scan.go
+++ b/pkg/sql/colfetcher/colbatch_scan.go
@@ -92,7 +92,12 @@ func (s *ColBatchScan) Next(ctx context.Context) coldata.Batch {
                if execinfra.ShouldCollectStats(s.ctx, s.flowCtx) {
                        // We need to start a child span so that the only contention events
                        // present in the recording would be because of this cFetcher.
-                       s.ctx, s.tracingSpan = execinfra.ProcessorSpan(s.ctx, "colbatchscan")
+                       sp := tracing.SpanFromContext(s.ctx)
+                       if sp == nil {
+                               panic("oops")
+                       }
+                       s.tracingSpan = sp
+                       // s.ctx, s.tracingSpan = execinfra.ProcessorSpan(s.ctx, "colbatchscan")
                }
        }
        bat, err := s.rf.NextBatch(s.ctx)

name                                 old time/op   new time/op   delta
KV/Scan/SQL/rows=1/sample_rate=X-16    266µs ± 7%    316µs ± 7%  +18.68%  (p=0.000 n=21+21)

name                                 old spans/op  new spans/op  delta
KV/Scan/SQL/rows=1/sample_rate=X-16     7.00 ± 0%     7.00 ± 0%     ~     (all equal)

[tbg]

So after all of this, it seems to me that there's evidence that something in SQL is slower when stats collection is enabled, even when tracing just drops all payloads on the floor and is thus definitely not incurring overhead for them, and even when the number of trace spans created is identical.

[awoods187]

Nice experiment!

[yuzefovich]

Thanks Tobi. I think the benchmark you wrote is a reasonable representation of how SQL propagates stats.

And yet, there's a 10% performance hit for the setting. What is the expensive thing we're doing? Creating more spans?

These are the questions I would like to know the answer to as well :)

As you found, we are creating an extra span in colbatch_scan, and I don't think we can get around that (without it we could be confusing contention events from different table readers running on the same node I think, to be confirmed), yet it doesn't appear to be the culprit.

I'll keep on looking at things to optimize in the SQL land (already found one #61529 which is responsible for a third of so of the performance hit). What puzzles me a bit is that usually I'm using profiles to guide the code optimization, but this time I'm not able to do that. I tried increasing CPU sampling rate (from default 100hz to 40000hz), and still the profiles aren't very helpful. The only strategy that appears to be working is simply commenting out parts that run once sampling is enabled and seeing whether it has any impact on the microbenchmark.

[tbg]

I share your confusion. I was trying to at least retroactively find the flowSpecToDiagram regression you just fixed (on this branch, which does not have the fix) but not a chance. I tried

#!/bin/bash

go test -c ./pkg/sql/tests
for rate in 0.0 1.0; do
env GOGC=off ./tests.test -test.run - -test.bench "BenchmarkKV/Scan/SQL/rows=1/sample_rate=${rate}" -test.benchtime=50000x
done

with this mod

@@ -317,12 +320,17 @@ func BenchmarkKV(b *testing.B) {
                                                                        b.Fatal(err)
                                                                }
                                                                numSpansBefore := kv.(*kvSQL).tr.Metrics().SpanCreated.Count()
+                                                               f, err := os.Create(fmt.Sprintf("%.2f.prof", sampleRate))
+                                                               require.NoError(b, err)
+                                                               defer f.Close()
                                                                b.ResetTimer()
+                                                               pprof.StartCPUProfile(f)
                                                                for i := 0; i < b.N; i++ {
                                                                        if err := opFn(kv, rows, i); err != nil {
                                                                                b.Fatal(err)
                                                                        }
                                                                }
+                                                               pprof.StopCPUProfile()
                                                                b.StopTimer()
                                                                numSpansAfter := kv.(*kvSQL).tr.Metrics().SpanCreated.Count()
                                                                b.ReportMetric(float64(numSpansAfter-numSpansBefore)/float64(b.N), "spans/op")

in the hope that go tool pprof -http :6060 -diff_base 0.00.prof 1.00.prof would at least have that method show up but nope. I did ultimately find it the top100 -cum at the very end for the 1.00 profile with focus=PlanAndRun:

     0.01s 0.061%  8.91%      0.58s  3.56%  github.com/cockroachdb/cockroach/pkg/sql.(*PlanningCtx).getDefaultSaveFlowsFunc.func1
         0     0%  8.91%      0.57s  3.50%  github.com/cockroachdb/cockroach/pkg/sql.(*PlanningCtx).flowSpecsToDiagram

PS @yuzefovich you may also want to rebase on top of #61359. There is a rando alllocation in startSpanGeneric that this PR fixes, which currently accounts for the bulk of time spent there:

.      150ms    379:	helper.crdbSpan.mu.structured.Reserve(maxStructuredEventsPerSpan)