sql: evaluate sql.txn_stats.sample_rate default

[asubiotto]

#59132 adds the sql.txn_stats.sample_rate cluster setting. The default setting is 0, which means never sample stats. However, we're soon going to change the DB Console page to show these sampled execution stats, which means that this setting has to be nonzero to show interesting information.

This issue tracks quantifying the performance effect of turning this setting up to always sample and seeing if it is realistic to remove this setting at all. If not, we might want to have a low but nonzero sample rate to provide some interesting data.

[yuzefovich]

Taking this over.

[yuzefovich]

Initial benchmarks suggest that using a sample rate of 0.5 or 1 has significant performance hit (on the order of 20%) on KV95 workload with 1 min ramp and 5 min duration on 3 node roachprod cluster:

• GCE:
  • sample_rate=0: 8584.3
  • sample_rate=0.5: 7777.8, -9.4%
  • sample_rate=1: 7120.9, -17.0%
• AWS:
  • sample_rate=0: 10485.8
  • sample_rate=0.5: 8934.1, -14.8%
  • sample_rate=1: 8237.3, -21.4%

Initial look at the profile suggests that crdbSpan.getRecording is to blame (the profile is over 30s):

[yuzefovich]

Looks like there are two main time usages there:

• assigning an entry to tracingpb.RecordedSpan.Tags map:

ROUTINE ======================== github.com/cockroachdb/cockroach/pkg/util/tracing.(*crdbSpan).getRecordingLocked.func1 in /go/src/github.com/cockroachdb/cockroach/pkg/util/tracing/crdbspan.go
         0      560ms (flat, cum)  0.98% of Total
         .          .    278:		rs.Finished = true
         .          .    279:	}
         .          .    280:
         .          .    281:	addTag := func(k, v string) {
         .          .    282:		if rs.Tags == nil {
         .       50ms    283:			rs.Tags = make(map[string]string)
         .          .    284:		}
         .      510ms    285:		rs.Tags[k] = v
         .          .    286:	}

• calling tag.ValueStr()
  It is possible that this comment is relevant:

ROUTINE ======================== github.com/cockroachdb/redact.StringWithoutMarkers in /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/redact/markers_print.go
      40ms      1.97s (flat, cum)  3.44% of Total
         .          .     91:// Note: if this function is ever found to be a performance
         .          .     92:// bottleneck, one can consider using an alternate implementation of
         .          .     93:// Sprint() which similarly calls the SafeFormat() methods but does
         .          .     94:// not introduce markers and instead writes to a string buffer
         .          .     95:// directly.
      10ms       10ms     96:func StringWithoutMarkers(f SafeFormatter) string {
      30ms      1.96s     97:	return Sprint(f).StripMarkers()
         .          .     98:}

that is being called by

         .          .     36:// String returns the node ID, or "?" if it is unset.
         .          .     37:func (n *NodeIDContainer) String() string {
      10ms      1.98s     38:	return redact.StringWithoutMarkers(n)

[tbg]

1. you're not accidentally starting verbose spans, right? Just to double check
2. I don't see why any tags would need to be added to the span. Tags are slow! I see code like this

cockroach/pkg/sql/flowinfra/outbox.go

Lines 221 to 225 in 5fd21c2

	if span != nil && span.IsVerbose() {
	m.statsCollectionEnabled = true
	span.SetTag(execinfrapb.FlowIDTagKey, m.flowCtx.ID.String())
	span.SetTag(execinfrapb.StreamIDTagKey, m.streamID)
	}

which makes it seem as though tags are somehow used to transport stats, which is not a good idea in the hot path. I think this is legacy code, but see if things like that are the problem.

3. do you see a similar slowdown in one of the in-process tests? It will be much more pleasant to iterate in a local setup.

[tbg]

I couldn't really see the same kind of drop on a local three node roachprod cluster running stock kv95, but I do see that #61116 removes the stringification of tags completely (as intended). Try with that PR and see if that helps.

[tbg]

Resulting flame graph (bit confusing thanks to recursion, but you get the idea)

[tbg]

This seems unnecessary - the spanstats put tags in the span:

[tbg]

^-- the CPU slice here isn't maybe all that big altogether, but the allocs I think are substantial:

[asubiotto]

Yeah, we've moved away from using tags in the spans (in favor of ComponentIDs in the ComponentStats proto) so we can probably remove that behavior.

[yuzefovich]

Thanks for looking into this Tobi!

Replying to your questions from #59379 (comment).

1. you're not accidentally starting verbose spans, right? Just to double check

I don't think so, we only use verbose spans when the tracing is enabled for the whole session or with EXPLAIN ANALYZE. I hope I'm not reading the code wrong here. Confirmed manually on my laptop that SetVerbose is not being called when we start sampling.

2. I don't see why any tags would need to be added to the span. Tags are slow! I see code like this

Ack. The code you linked gets executed only is the verbose tracing is enabled. I did find a few thing (#61158) where we would be setting tags in non-verbose tracing. Rerunning my benchmarks with both #61116 and #61158 cherry-picked, and I see an improvement, but the hit with tracing "always on" is still very high - on the order of 1510%.

3. do you see a similar slowdown in one of the in-process tests? It will be much more pleasant to iterate in a local setup.

I haven't tried any of the local benchmarks yet, but I'll post here if I find something useful.

[yuzefovich]

The numbers I got yesterday with both #61158 and #61116 cherry-picked with 3 min ramp and 15 min duration:

• GCE:
  • sample_rate=0: 9335.7
  • sample_rate=0.05: 9235.3, -1.1%
  • sample_rate=0.1: 9211.2, -1.3%
  • sample_rate=0.15: 9078.7, -2.8%
• AWS:
  • sample_rate=0: 10636.2
  • sample_rate=0.05: 10488.1, -1.4%
  • sample_rate=0.1: 10481.1, -1.5%
  • sample_rate=0.15: 10347.0, -2.7%

[asubiotto]

Nice! That looks promising cc @awoods187 @jordanlewis. What's the bottleneck now?

[awoods187]

This is interesting. I was having to push into 0.5 values to see meaningful values for network and memory when running tpc-c with 10 warehouses via roachprod local previously.

I'm concerned that too low a sampling value will result in these columns being largely empty and a too high value causing significant performance degradation. Even the values of .15 impact the cluster 2.7%, something we haven't been willing to do in the past with optimizer or other execution changes.

[asubiotto]

Note that this is with the sampling rate fully turned on. Oops my bad

[yuzefovich]

I implemented all hacky ideas mentioned so far in https://github.com/yuzefovich/cockroach/commits/sample-rate, however, this didn't change microbenchmark numbers nor KV95 numbers on 3 node cluster.

When looking at the profiles of 3 node cluster with sample_rate=1 I see some time spent in getRecording and ExtractStatsFromSpan. However, when diving into details I don't see much we can chop off - to me it all seems like propagating the execution stats through traces has inherent overhead which shows up as the performance hit. On 30 seconds profile I see this:

ROUTINE ======================== github.com/cockroachdb/cockroach/pkg/util/tracing.(*crdbSpan).getRecording in /go/src/github.com/cockroachdb/cockroach/pkg/util/tracing/crdbspan.go
      60ms      1.88s (flat, cum)  3.39% of Total
...
         .      190ms    167:	result := make(Recording, 0, 1+len(s.mu.recording.children)+len(s.mu.recording.remoteSpans))
         .          .    168:	// Shallow-copy the children so we can process them without the lock.
      10ms       10ms    169:	children := s.mu.recording.children
         .      620ms    170:	result = append(result, s.getRecordingLocked(wantTags))
      10ms       50ms    171:	result = append(result, s.mu.recording.remoteSpans...)
         .       70ms    172:	s.mu.Unlock()
         .          .    173:
         .          .    174:	for _, child := range children {
      20ms      680ms    175:		result = append(result, child.getRecording(everyoneIsV211, wantTags)...)
         .          .    176:	}
         .          .    177:
         .          .    178:	// Sort the spans by StartTime, except the first Span (the root of this
         .          .    179:	// recording) which stays in place.
         .       50ms    180:	toSort := sortPool.Get().(*Recording) // avoids allocations in sort.Sort
      10ms       10ms    181:	*toSort = result[1:]
      10ms      150ms    182:	sort.Sort(toSort)
         .          .    183:	*toSort = nil
         .       30ms    184:	sortPool.Put(toSort)
ROUTINE ======================== github.com/cockroachdb/cockroach/pkg/util/tracing.(*crdbSpan).getRecordingLocked in /go/src/github.com/cockroachdb/cockroach/pkg/util/tracing/crdbspan.go
      40ms      620ms (flat, cum)  1.12% of Total
...
      20ms       30ms    299:	if numEvents := s.mu.structured.Len(); numEvents != 0 {
         .       10ms    300:		rs.InternalStructured = make([]*types.Any, 0, numEvents)
         .          .    301:		for i := 0; i < numEvents; i++ {
         .       20ms    302:			event := s.mu.structured.Get(i).(Structured)
         .      480ms    303:			item, err := types.MarshalAny(event)
         .          .    304:			if err != nil {
         .          .    305:				// An error here is an error from Marshal; these
         .          .    306:				// are unlikely to happen.
         .          .    307:				continue
         .          .    308:			}
         .          .    309:			rs.InternalStructured = append(rs.InternalStructured, item)
         .          .    310:		}
         .          .    311:	}

ROUTINE ======================== github.com/cockroachdb/cockroach/pkg/sql/execinfrapb.ExtractStatsFromSpans.func1 in /go/src/github.com/cockroachdb/cockroach/pkg/sql/execinfrapb/component_stats.go
      20ms      460ms (flat, cum)  0.83% of Total
...
      20ms       20ms    345:		span.Structured(func(item *types.Any) {
         .       30ms    346:			if !types.Is(item, componentStats) {
         .          .    347:				return
         .          .    348:			}
         .       40ms    349:			stats := NewComponentStats()
         .      340ms    350:			if err := protoutil.Unmarshal(item.Value, stats); err != nil {
         .          .    351:				return
         .          .    352:			}

At this point, I don't know what else to try to reduce the performance hit. Curious to hear whether @tbg or @irfansharif have some suggestions.

I've been using this script (no judgement please, I'm a bash noob :D) to run the KV95 benchmarks if anyone is interested in running it themselves.

[tbg]

The meta question that I have is why we're blaming tracing right now. My experiments over in #61328 (comment) (which I'd like you to scrutinize/confirm! I might have messed something up) indicate that the overhead of stats collection related to marshalling, transporting, unmarshalling the extra payloads should be in the single-digit microsecond range, but I see more like 40 microseconds in the single-in-mem-server benchmark. Let's discuss over on #61328.

[asubiotto]

It's possible that something else is slowing this down. The VectorizedStatsCollector might be slowing things down when inserted into a flow. It's possible that we should also experiment with pooling all operators in this flow to see what the change is. Since it's hard to see anything from the profiles, I think the way forward here is to list the differences between a non-instrumented flow and an instrumented flow and try to narrow down the search surface area by e.g. experimenting with not allocating stats collectors at all, or making batchInfoCollector.Next not do anything.

[tbg]

Note that ./cmp.sh (the macrobenchmark) intentionally disables garbage collection, so I don't think pooling should make a difference in at least that benchmark.

[yuzefovich]

Quick update is that with #61529 cherry-picked, the performance hit of sample_rate=1 went down noticeably, to -5.7% on GCE and -7.1% on AWS in a single 5 min run.

[yuzefovich]

In my experiments on df11d41 with Tobi's commits from #61328 cherry-picked (but without mine WIP commits) I observe the following explanation for the current 13% perf hit in the macro benchmark (KV/Scan, all numbers are approximate):

• 1% hit for simply creating a new span (the one in instrumentationHelper.Setup) and finishing it, without getting the recording. No stats are collected.
• 2-3% hit for getting the recording from that span when no stats have been attached to it. We're getting the trace data that is attached by other components (most likely below SQL, like dist sender).
• 1.5% for saving flows metadata by saveFlows function when there are no stats attached still. saveFlows also calls NewFlowsMetadata. It seems like NewFlowsMetadata is currently responsible for about half of 1.5% hit.
• 2.5% for calling GetQueryLevelStats on a trace with no stats payload. Note that recording query level stats into appStats and txnStats seems to be free.
• 2% for planning vectorized stats collectors, but without calling getStats on them and, therefore, still not adding stats payload to the trace.
• 1.5% for calling getStats (i.e. retrieving the execution stats) but still not attaching them to the trace.
• 1.5% for attaching the stats to the trace (i.e. performing the full action for sampling).

[yuzefovich]

I prototyped again a few things already mentioned before to see the impact on an actual KV95 run here.

• the first commit removes an extra span created in instrumentationHelper.Setup and uses the already present one. This change seems to reduce the hit by a quarter or so. The numbers look as follows:
  • GCE:
    • sample_rate=0.5: -0.8%
    • sample_rate=1: -4.1%
  • AWS:
    • sample_rate=0.5: -3.5%
    • sample_rate=1: -6.7%
• the second commit trims the trace analyzer to remove currently unused bookkeeping. This commit surprisingly seems to have thing a bit worse actually. The numbers look as follows:
  • GCE:
    • sample_rate=0.5: -3.0%
    • sample_rate=1: -6.8%
  • AWS:
    • sample_rate=0.5: -4.7%
    • sample_rate=1: -6.2%
• the third commit pools ComponentStats objects. Note that the second commit made it easier to implement this commit. The numbers look as follows:
  • GCE:
    • sample_rate=0.5: -3.2%
    • sample_rate=1: -6.9%
  • AWS:
    • sample_rate=0.5: -2.7%
    • sample_rate=1: -5.0%
• the fourth commit removes the additional tracing span created by the colbatchscans. Note that in the current form that commit cannot be merged to master because it would cause confusion during the computation of cumulative contention time when there are wrapped rowexec processors in the vectorized flow. The numbers look as follows:
  • GCE:
    • sample_rate=0.5: -3.8%
    • sample_rate=1: -5.4%
  • AWS:
    • sample_rate=0.5: -0.0%
    • sample_rate=1: -2.4%

---

Based on these results, it looks like the most beneficial thing is avoiding creating spans if possible. Thus, I'll open up a PR to include the first commit and will kick off more extensive benchmarks with it.

[yuzefovich]

With #61532 I got the following (3 numbers indicate durations of 5 min, 10 min, and 15 min, respectively):

• GCE:
  • sample_rate=0.05: +1.6%, -1.4%, +0.3%
  • sample_rate=0.1: +1.6%, -1.0%, +1.3%
  • sample_rate=0.25: -0.2%, -2.8%, -2.6%
  • sample_rate=0.5: -2.5%, -4.5%, -3.0%
  • sample_rate=1: -2.8%, -7.3%, -5.8%
• AWS:
  • sample_rate=0.05: -2.2%, -0.7%, -0.8%
  • sample_rate=0.1: -0.1%, -0.6%, -1.0%
  • sample_rate=0.25: -1.1%, -1.8%, -2.4%
  • sample_rate=0.5: -3.3%, -3.6%, -3.3%
  • sample_rate=1: -7.4%, -6.8%, -6.3%

[yuzefovich]

Reran the tests on 90d6ba4 with #61532 (Tobi suggested that #61359 might improve things). Looks like without other improvements sample_rate=0.1 will be the maximum recommended default value. The numbers are for 5 min and 10 min duration:

• GCE:
  • sample_rate=0.05: -1.8%, -0.4%
  • sample_rate=0.1: -2.0%, -1.1%
  • sample_rate=0.25: -3.1%, -2.0%
  • sample_rate=0.5: -5.1%, -2.7%
  • sample_rate=1: -8.4%, -5.6%
• AWS:
  • sample_rate=0.05: -2.2%, -0.6%
  • sample_rate=0.1: -1.5%, -1.6%
  • sample_rate=0.25: -3.1%, -3.2%
  • sample_rate=0.5: -5.1%, -4.6%
  • sample_rate=1: -8.9%, -8.6%

[asubiotto]

Let's set it to 0.1. I'll try to circle back later with a better sampling approach (i.e. sample the first occurrence of a fingerprint) in #61678.

[irfansharif]

I've yet to digest the experiments here and on #61328, but looking at TPC-C I'm seeing about 10% additional memory usage by just us creating new spans (mostly from connExecutor.execCmd): #59424 (comment). I don't suppose we can do much about that one, can we? I haven't worked out how that affects CPU usage. We're certainly taking on added GC pressure because of it. In any case, the memory overhead seems a bit worrying.

[irfansharif]

Hm, ok just familiarized myself with the above. I guess that one is pretty necessary. The analysis here and on #61328 look sound, y'all are way ahead of me. Just a sanity check (esp cause the %s above are using 5-15m runs), we arrived at 0.1 with GC switched on, right?