tracing: unexpected significant overhead under sysbench when tracing is off (0.3% allocs 1.6% cpu)

[tbg]

In profile from https://github.com/cockroachlabs/perf-efficiency-team/pull/4 (oltp_read_write)
5% is very significant. Is this all on by accident?

Jira issue: CRDB-43624

[tbg]

https://cockroachlabs.slack.com/archives/C06KHP4PU4X/p1729810236138319?thread_ts=1729720298.418539&cid=C06KHP4PU4X

The tl;dr is that there's logic to make sure that we sample with structured recording for 1% of transaction and for every statement fingerprint we've not previously sampled. That's all fine and good, except that we never ever write into our stats collector that BEGIN TRANSACTION or END TRANSACTION have been sampled. This leads to something very funny: all END TRANSACTION statements end up being traced with structured recording.

[tbg]

in #133132 (review) I'm seeing wayyy under 0.5%. I'm unsure why that is - @nvanbenschoten any ideas, is the microbenchmark not tickling this in the same way?

[nvanbenschoten]

I'm unsure why that is - @nvanbenschoten any ideas, is the microbenchmark not tickling this in the same way?

One thought is that serverutils.StartServerOnly might be disabling more of the SQL server than expected.

[dhartunian]

Ack that Observability team will pick this up in Nov milestone. Will get back to y'all if it turns out to be a heavy lift and we need to re-evaluate.

[tbg]

Just wanted to point out that there's also something potentially unexpected here:

https://cockroachlabs.slack.com/archives/C06KHP4PU4X/p1729810236138319?thread_ts=1729720298.418539&cid=C06KHP4PU4X

Aside: the statement stats flushing is pretty intense -- the math on the number of unique statement fingerprints being flushed doesn't really add up to the number of PersistedSQLStats.upsertStatementStats. We see that PersistedSQLStats.MaybeFlush takes 3 minutes... We have an interesting chart of it running statements at the bottom.

[tbg]

more paper trail: setting the various cluster settings

		roachprod sql "${cluster}:1" -- -e 'set cluster setting sql.txn_stats.sample_rate = 0;'
		roachprod sql "${cluster}:1" -- -e 'set cluster setting sql.metrics.statement_details.enabled = false;'
		roachprod sql "${cluster}:1" -- -e 'set cluster setting sql.metrics.transaction_details.enabled = false;'

doesn't seem to provide a workaround. I'm still seeing it in the profiles.

https://cockroachlabs.slack.com/archives/C06301L45NF/p1730217788024329?thread_ts=1730215659.655189&cid=C06301L45NF

[tbg]

Update on the overhead. The below is on 6a7b1e2 on oltp_read_only. This still seems pretty bad.
profile.pb.gz

[dhartunian]

Given that the overhead is within SpanFromContext, there aren't many options available to us. Plumbing down additional state from the tracer into the logging context seems challenging to do. Part of the appeal of logging with a ctx is that the caller doesn't need to worry about this and it would be nice to preserve all the callsites without modification.

One reason that we pay such a large cost is that in the case of a "no tracing" context, we need to traverse the entire tree to be able to tell if a context contains a span or not, there's no way to "exit early".

Given that we already use a custom patched runtime, could we modify the context package to do this for us? There are two options that come to mind:

1. We can introduce a hasSpan boolean that's propagated upwards into the context stack anytime a valueCtx containing the span key is wrapped. This would allow us to do a "fast check" at the top of the stack. However, this expands the size of the context structs which is probably undesirable given their widespread usage.

2. An alternative is that we can introduce a spanCtx struct that is the official "span container". valueCtx is no longer used to carry spans. Whenever a spanCtx is wrapped with a different parent, we can invert the wrapping and always hoist the spanCtx to the outer layer. This would allow us to just check the outer type of the Context implementation. If it's a spanCtx we extract the span, otherwise we know that spanCtx could not exist in the context chain because if it did, it would bubble to the top.

Maybe something like this: (of course the behavior would have to be extended to all the other context types. I'm unsure of the complexity involved there.)

type spanCtx struct {
	Context
	span *Span
}

func WithSpan(parent Context, span *Span) Context {
	return &spanCtx{parent, span}
}

func (c spanCtx) Span() *Span {
	return c.span
}

func WithValue(parent Context, key, val any) Context {
	if parent == nil {
		panic("cannot create context from nil parent")
	}
	if key == nil {
		panic("nil key")
	}
	if !reflectlite.TypeOf(key).Comparable() {
		panic("key is not comparable")
	}
	if ss, ok := parent.(*spanCtx); ok {
		return &spanCtx{&valueCtx{ss.Context, key, val}, ss.span}
	}
	return &valueCtx{parent, key, val}
}

// This implementation is possible because if there was a `spanCtx` in
// the parent chain, it would have "bubbled" to the top during
// wrapping. If we're asking a valueCtx for a `Span` it means the
// `spanCtx` does not exist in this chain.
func (c *valueCtx) Span() *Span {
	return nil
}

@tbg do you think this is a direction worth pursuing? It seems like the "giant context chain" problem is widespread.

I haven't spent time thinking through the other tracing package perf hits in your pprof screenshot yet.

[dhartunian]

A few things I tried today that I'm not confident in but will revisit:

Modifying code from this:

func (opts *spanOptions) recordingType() tracingpb.RecordingType {
	if opts.recordingTypeExplicit {
		return opts.recordingTypeOpt
	}

	var recordingType tracingpb.RecordingType
	if !opts.Parent.empty() && !opts.Parent.IsNoop() {
		recordingType = opts.Parent.i.crdb.recordingType()
	} else if !opts.RemoteParent.Empty() {
		recordingType = opts.RemoteParent.recordingType
	}
	if recordingType < opts.minRecordingTypeOpt {
		recordingType = opts.minRecordingTypeOpt
	}
	return recordingType
}

to this:

func (opts *spanOptions) recordingType() tracingpb.RecordingType {
	if opts.recordingTypeExplicit {
		return opts.recordingTypeOpt
	}

	var recordingType tracingpb.RecordingType
	if opts.Parent.NotEmptyNotNoop() { // combining checks avoids a copy
		recordingType = opts.Parent.i.crdb.recordingType()
	} else if !opts.RemoteParentEmpty { // This is a bool now, avoid struct copy
		recordingType = opts.RemoteParent.recordingType
	}
	if recordingType < opts.minRecordingTypeOpt {
		recordingType = opts.minRecordingTypeOpt
	}
	return recordingType
}

This felt like making a bigger mess by duplicating logic and adding more fields to a struct thats gets copied often. I think I'll try to make these values precomputed instead. The SpanOptions struct should just know its recording type after construction instead of requiring so much dynamic lookup.

[ajwerner]

One note on #135567 is that it won't work for folks using the cockroach-go library or who have implemented retry loops as the docs recommend. Namely, we also will never thing we've sampled RELEASE SAVEPOINT cockroach_restart, which happens to magically internally perform a commit. Same goes for the equally magical SHOW COMMIT TIMESTAMP statement.