kvserver: add stack history to trace of slow requests

[dt]

First commit is #97829.

This uses the new tracing.MaybeRecordStackHistory helper to add any recorded history
of the request evaluation's stack to the trace before returning the result (success or
error) if the request is considered to have been 'slow'. A new setting controls how slow
a request must be to trigger a search for the history of its stack, and that history is only
available if and at the granularity controlled by trace.snapshot.rate setting.

A history of the stack can be particularly useful when a request returns an error caused
by a timeout or context cancellation, as often by the time such a request is returning, it
is no longer at the same point where it spent all the time that caused it to be so slow.
Instead, this patch in conjunction with the tracer's snapshotting facility allows asking
'what was i doing all that time?' and having the tracer answer, even if the code asking
was doing work that was not directly instrumented to make itself visible in traces.

Example statement bundle trace, after sprinkling some sleeps in pkg/storage code (trimmed for brevity):

Fixes: #98304

Release note (ops change): the setting kv.slow_requests.trace_stack_history.threshold can be used to attach available stack history from tracer snapshots to the trace of slow requests.
Epic: none.

[cockroach-teamcity]

This change is 

[tbg]

+1 on the basic approach if we are sure enough that it won't cause fallout on unrelated operations (overload, mem spikes, etc, but if it's opt-in the bar is somewhat lower). I think the obs-folks should lead the review and I will unassign, but this looks like it could save a lot of time on stuck DR operations.

[dt]

if it's opt-in

it is opt-in for now.

I asked @irfansharif if he had rough guesses on latency impact of grabbing stacks and he points out that so few goroutines are actually runnable at a time that it is likely negligible. I'm testing this patch right now on roachprod with ycsb-f and see nothing in p90 or p9999 (enabled at :50) :

[andreimatei]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)

---

-- commits line 22 at r2:
Apropos nothing, are you aware of golang/go#57928 ? Seems like we'll get a callback when a ctx's timeout expires.

---

pkg/kv/kvserver/store_send.go line 209 at r3 (raw file):

		br, writeBytes, pErr = repl.SendWithWriteBytes(ctx, ba)
		if timeutil.Since(startedAt) > slowRequestHistoricalStackThreshold.Get(&s.ClusterSettings().SV) {
			repl.Tracer.MaybeRecordStackHistory(ctx, "slow kv request", startedAt)

The store seems like a pretty arbitrary place to put this. Can we lift it to the node?

---

pkg/util/tracing/tracer_snapshots.go line 97 at r1 (raw file):

	})
	if automatic {
		id = id * -1

The first automatic snapshot is gonna have ID -1. Then the next one is gonna do (-1 + 1) above, and then 0 * -1 here, no?

I think the whole spiel with negative IDs is confusing. I can't really tell who deals with positive ones and who deals with negatives. I think it'd probably be better if we made the IDs unique across the two buffers - even if this means we can no longer take an ID and directly turn it into a buffer offset.
I think we should also attach a collection reason to each snapshot, and those can be used by the UI to differentiate the automatic ones.

---

pkg/util/tracing/tracer_snapshots.go line 149 at r1 (raw file):

}

// GetSnapshots returns info on all stored span snapshots.

I think now it's worth saying something about the order of the results.

---

pkg/util/tracing/tracer_snapshots.go line 242 at r1 (raw file):

		t.autoSnapRateChange = make(chan struct{}, 1)
	} else if !buildutil.CrdbTestBuild {
		panic("this tracer already started periodic snapshots")

I doubt that it's worth making this assertion only run in tests; make it unconditional.

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

// such automatic snapshots are available to be searched and if so at what
// granularity.
func (t *Tracer) MaybeRecordStackHistory(ctx context.Context, op string, since time.Time) {

This methods uses both t and sp.Tracer(). The two are not necessarily the same - in particular each shared-proc tenant has its own Tracer. As a matter of principle, it's better to not start from both a span and a tracer. Let's make this a method on the Span.

---

pkg/util/tracing/tracer_snapshots.go line 314 at r2 (raw file):

			return
		}
		if stack, ok := s.Stacks[id]; ok {

I think you want to break on the first !ok and maybe record one more message.

---

pkg/util/tracing/tracer_snapshots.go line 315 at r2 (raw file):

		}
		if stack, ok := s.Stacks[id]; ok {
			// TODO(dt): make this structured?

I would start with what you have now.

---

pkg/util/tracing/tracer_snapshots.go line 316 at r2 (raw file):

		if stack, ok := s.Stacks[id]; ok {
			// TODO(dt): make this structured?
			sp.Recordf("%s:%d: %s had following stack as of %.1fs ago: %s",

I think this can be a lot of data that might impact our per-trace bytes limits, causing random parts of a trace to be dropped. I think we should do at least a minimal effort to dedup - like don't log completely identical stacks multiple times.

[dt]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @andreimatei)

---

-- commits line 22 at r2:

Previously, andreimatei (Andrei Matei) wrote…

Apropos nothing, are you aware of golang/go#57928 ? Seems like we'll get a callback when a ctx's timeout expires.

I was not. huh, cond vars might finally be useful.

But how is it 2023 and ctx cancellation still doesn't compose with mutex acquisition?

---

pkg/util/tracing/tracer_snapshots.go line 97 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

The first automatic snapshot is gonna have ID -1. Then the next one is gonna do (-1 + 1) above, and then 0 * -1 here, no?

I think the whole spiel with negative IDs is confusing. I can't really tell who deals with positive ones and who deals with negatives. I think it'd probably be better if we made the IDs unique across the two buffers - even if this means we can no longer take an ID and directly turn it into a buffer offset.
I think we should also attach a collection reason to each snapshot, and those can be used by the UI to differentiate the automatic ones.

yeah, sorry, there is some subtlety in where this is negated, specifically this after we've put the (still positive) ID into the ring buff, so when we call it next time, we're going to do (1+1) = 2, then 2 * -1 = -2, etc.

If we want to keep the pos/neg thing, I could add comment, but basically: in the ring buffer: all positive IDs. In the public methods: positive = user, negative = auto. We flip negative to positive in Get after picking the auto slice to look in, and we flip positive to negative when we return the SnapshotInfos for automatic in Get[].

I donno, I could change the protos, the admin service, the js, etc but it seemed easier just to utilize the other half of the int space we wen't using and since these "IDs" aren't really important to anyone anyway (and are reused after reboot or whatever).

I'm almost tempted to just make "ID" captured-at nanos instead of a separate field, and have Get() do a linear search of both rings for a match, but figured someone wouldn't like that, and just went with this (under commented but I think not to complicated) scheme?

---

pkg/util/tracing/tracer_snapshots.go line 242 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I doubt that it's worth making this assertion only run in tests; make it unconditional.

it's actually not run in tests, because my unit test manually init's the channel so it can init it to an unbuffered channel and then be able to move between steps the test in lockstep.

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

This methods uses both t and sp.Tracer(). The two are not necessarily the same - in particular each shared-proc tenant has its own Tracer. As a matter of principle, it's better to not start from both a span and a tracer. Let's make this a method on the Span.

So I actually did this intentionally (but probably should have commented):

First: sp.Tracer is used where it is used because we don't bother recording if the tracer for the span into which we are going to record isn't going to use our recording -- if that tracer, to which this span belongs, isn't using the record, skip it. That seems right?

Second: if a goroutine in kvserver says "I want to record what I was doing for the last 3 minutes", I think it should search in the stack history that is being maintained -- or not -- for the kvserver, which is to say, it should be searching the automaticSnapshots captured, or not, in the kvserver's Tracer (which is also the system tenant's tracer). If the system tenant has configured 3s snapshots or 30s snapshots with the system tenant's setting, that'll affect what is in the system tenant's tracer and thus is the tracer we should be searching when the system tenant -- in this case the kvserver -- comes asking. Or more generally, the caller who is asking to search goroutines should be calling that on a tracer of their choice.

So I think it is Good, Actually, that this is using both t and sp.Tracer. does my reasoning sway you?

---

pkg/util/tracing/tracer_snapshots.go line 316 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think this can be a lot of data that might impact our per-trace bytes limits, causing random parts of a trace to be dropped. I think we should do at least a minimal effort to dedup - like don't log completely identical stacks multiple times.

yeah, diffing was next up but I wanted to validate the broad approach first.

[dt]

@andreimatei would you rather have a more narrowly-scoped discussion of the snapshotting functionality and API in isolation on #97829 and then visit the stack searching/trace annotating side of it only once we we have background snapshots settled?

[andreimatei]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, dt (David Taylor) wrote…

So I actually did this intentionally (but probably should have commented):

First: sp.Tracer is used where it is used because we don't bother recording if the tracer for the span into which we are going to record isn't going to use our recording -- if that tracer, to which this span belongs, isn't using the record, skip it. That seems right?

Second: if a goroutine in kvserver says "I want to record what I was doing for the last 3 minutes", I think it should search in the stack history that is being maintained -- or not -- for the kvserver, which is to say, it should be searching the automaticSnapshots captured, or not, in the kvserver's Tracer (which is also the system tenant's tracer). If the system tenant has configured 3s snapshots or 30s snapshots with the system tenant's setting, that'll affect what is in the system tenant's tracer and thus is the tracer we should be searching when the system tenant -- in this case the kvserver -- comes asking. Or more generally, the caller who is asking to search goroutines should be calling that on a tracer of their choice.

So I think it is Good, Actually, that this is using both t and sp.Tracer. does my reasoning sway you?

It doesn't really sway me :P
You're saying that it can be useful to call this on the kvserver tracer and pass in a tenant span, but I don't think that's a realistic proposition - if the caller is kv then it can't get its hands on a tenant span, and if the caller is a tenant then it can't get its hands on the kv tracer. So I don't think the confusion arising from the multiple tracers is worth it.
I'd suggest we start by not worrying about this kind of mixing at all unless you actually have a specific need in mind. If it proves needed later, maybe we think more about how to do it - for example, if the issue is that we want tenant spans to have the stacks but enabling the snapshots is only ever done at the KV level, perhaps the answer is to give tenant tracers a reference to a shared snapshot registry. But there's privacy concerns I guess, and you're already flirting with privacy questions with the current code.

[dt]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @andreimatei)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

It doesn't really sway me :P
You're saying that it can be useful to call this on the kvserver tracer and pass in a tenant span, but I don't think that's a realistic proposition - if the caller is kv then it can't get its hands on a tenant span, and if the caller is a tenant then it can't get its hands on the kv tracer. So I don't think the confusion arising from the multiple tracers is worth it.
I'd suggest we start by not worrying about this kind of mixing at all unless you actually have a specific need in mind. If it proves needed later, maybe we think more about how to do it - for example, if the issue is that we want tenant spans to have the stacks but enabling the snapshots is only ever done at the KV level, perhaps the answer is to give tenant tracers a reference to a shared snapshot registry. But there's privacy concerns I guess, and you're already flirting with privacy questions with the current code.

Let me break this into a couple discrete points and we can see which we agree on and where we differ to see why we're coming to different conclusions here:

(1) adding execution information to the kv response (in its trace), including information about what the stack within the KV server was at various points while it was executing that request, is the responsibility of the kvserver executing that request

(2) since it is a kvserver behavior, the kvserver should be consulting the kvserver's persisted stack history to find this information, that is capturing at its configured interval/retention/etc

(3) whether or not a given span will make use of the information is determined by the span that owns that tracer

(4) we shouldn't bother adding information to the trace if it won't be used

To me, (1) + (2) suggests that augmenting the trace with stack info should be a method of tracer, that the kvserver calls on its tracer while (3) + (4) suggest that sp.Tracer.HasExternalSink is the right conditional for skipping pointless recording.

As far as privacy: that's why I didn't let you ask for any goroutine: you can just ask about yourself, since the time you started your current request, so I don't think you're finding anything out about any other requests really?

[andreimatei]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, dt (David Taylor) wrote…

Let me break this into a couple discrete points and we can see which we agree on and where we differ to see why we're coming to different conclusions here:

(1) adding execution information to the kv response (in its trace), including information about what the stack within the KV server was at various points while it was executing that request, is the responsibility of the kvserver executing that request

(2) since it is a kvserver behavior, the kvserver should be consulting the kvserver's persisted stack history to find this information, that is capturing at its configured interval/retention/etc

(3) whether or not a given span will make use of the information is determined by the span that owns that tracer

(4) we shouldn't bother adding information to the trace if it won't be used

To me, (1) + (2) suggests that augmenting the trace with stack info should be a method of tracer, that the kvserver calls on its tracer while (3) + (4) suggest that sp.Tracer.HasExternalSink is the right conditional for skipping pointless recording.

As far as privacy: that's why I didn't let you ask for any goroutine: you can just ask about yourself, since the time you started your current request, so I don't think you're finding anything out about any other requests really?

The way I see it, if you want to insist that it's a good thing to be explicit about which Tracer you're getting stack information from, then I think it'd be better to have a Tracer method that queries the registry for the stacks, and lift the recording of that information into a span out. A Tracer method that takes a span that might have been created by a different Tracer is weird.

But still, I don't think that being explicit about the tracer is needed (is it?). I understand the separation of concerns that you're explaining, but still I think you'd have a significantly simpler API if you made this a span method, and implicitly used the span's tracer. Most code doesn't have a reference to a Tracer.
I'll ask again - will any caller have a tenant span and a reference to the KV Tracer? I doubt it...
And if you do envision such a case, then again I'd argue that a better solution would be to make these automatic snapshots available to all the tracers by linking them at server startup, rather than asking tenants to somehow get their hands on the kv tracer.

If none of this sways you, I'll take the code as it is.

[dt]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @andreimatei)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

will any caller have a tenant span

Does a tenant-sql-created kv request keep its tenant-tracer-owned span when it is being evaluated server-side?

Okay, another idea: what if we took the current code -- one method on one tracer that takes a span and records into it -- but you didn't see sp.Tracer() in the middle of it, and instead instead just a sp.RecordingIsVerboseOrHasConsumer() ?

[andreimatei]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Does a tenant-sql-created kv request keep its tenant-tracer-owned span when it is being evaluated server-side?

No.
This code here on the tenant side and here on the server side conspire to give the rpc handler a new span belonging to the kv tracer.

Okay, another idea: what if we took the current code -- one method on one tracer that takes a span and records into it -- but you didn't see sp.Tracer() in the middle of it, and instead instead just a sp.RecordingIsVerboseOrHasConsumer() ?

Heh, I wanted to preempt this before but tried to keep my comments shorter.
It's not the use of both t and sp.Tracer that bothers me (although this brings the discussion to the forefront); it's the use of t and sp. I don't want that t at all - particularly because most code shouldn't have a Tracer at all; most code just gets a span from the ctx.

[dt]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @andreimatei)

---

pkg/util/tracing/tracer_snapshots.go line 149 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think now it's worth saying something about the order of the results.

No longer relevant.

---

pkg/util/tracing/tracer_snapshots.go line 242 at r1 (raw file):

Previously, dt (David Taylor) wrote…

it's actually not run in tests, because my unit test manually init's the channel so it can init it to an unbuffered channel and then be able to move between steps the test in lockstep.

Done.

(Discussed on base PR)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Does a tenant-sql-created kv request keep its tenant-tracer-owned span when it is being evaluated server-side?

No.
This code here on the tenant side and here on the server side conspire to give the rpc handler a new span belonging to the kv tracer.

Okay, another idea: what if we took the current code -- one method on one tracer that takes a span and records into it -- but you didn't see sp.Tracer() in the middle of it, and instead instead just a sp.RecordingIsVerboseOrHasConsumer() ?

Heh, I wanted to preempt this before but tried to keep my comments shorter.
It's not the use of both t and sp.Tracer that bothers me (although this brings the discussion to the forefront); it's the use of t and sp. I don't want that t at all - particularly because most code shouldn't have a Tracer at all; most code just gets a span from the ctx.

Done.

Okay, thanks for talking me through all this; I'm convinced. Switched to method on Span.

---

pkg/util/tracing/tracer_snapshots.go line 314 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think you want to break on the first !ok and maybe record one more message.

Done.

---

pkg/util/tracing/tracer_snapshots.go line 315 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I would start with what you have now.

Switched to structured anyway to represent the digit.

---

pkg/util/tracing/tracer_snapshots.go line 316 at r2 (raw file):

Previously, dt (David Taylor) wrote…

yeah, diffing was next up but I wanted to validate the broad approach first.

Added diffing.

---

pkg/kv/kvserver/store_send.go line 209 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

The store seems like a pretty arbitrary place to put this. Can we lift it to the node?

Done.

[andreimatei]

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @adityamaru and @dt)

---

pkg/util/tracing/tracer_snapshots.go line 294 at r2 (raw file):

Previously, dt (David Taylor) wrote…

Done.

Okay, thanks for talking me through all this; I'm convinced. Switched to method on Span.

👍

---

pkg/util/tracing/tracer_snapshots.go line 313 at r5 (raw file):

	}
	t := sp.Tracer()
	if !sp.IsVerbose() && !t.HasExternalSink() {

do sp.i.hasVerboseSink() now that you're inside the span

---

pkg/util/tracing/tracingpb/recorded_span.proto line 181 at r6 (raw file):

  option (gogoproto.goproto_stringer) = false;
  string stack = 1;
  int32 shared_suffix = 2;

please comment these 2 fields

---

pkg/util/tracing/tracingpb/recorded_span.proto line 183 at r6 (raw file):

  int32 shared_suffix = 2;
  int32 shared_lines = 3;
  int64 age = 4 [(gogoproto.casttype) = "time.Duration"];

consider making this a timestamp so it's more meaningful on its own

---

pkg/util/tracing/tracingpb/recorded_span.proto line 184 at r6 (raw file):

  int32 shared_lines = 3;
  int64 age = 4 [(gogoproto.casttype) = "time.Duration"];
  // NEXT ID: 5.

nit: I vote we stay away from these comments. Reserving old ids I think is the common practice.

[dt]

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @adityamaru and @andreimatei)

---

pkg/util/tracing/tracer_snapshots.go line 314 at r2 (raw file):

Previously, dt (David Taylor) wrote…

Done.

I changed my mind on this and decided to iterate from oldest snapshot to newest instead of new-to-old and break when it gets too old; Yes, this does mean I expect to step through the too-old snapshots but that should be cheap enough to just do a few integer comparisons to skip each of a small, bounded set, and it means it is easy to record them in old-to-new order which seems worth it, and made the code much simpler to follow.

---

pkg/util/tracing/tracer_snapshots.go line 313 at r5 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

do sp.i.hasVerboseSink() now that you're inside the span

Done.

Ah, even better.

---

pkg/util/tracing/tracingpb/recorded_span.proto line 181 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

please comment these 2 fields

Done.

---

pkg/util/tracing/tracingpb/recorded_span.proto line 183 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

consider making this a timestamp so it's more meaningful on its own

I actually started with a timestamp but switched to this; is a timestamp meaningful on its own?

I was thinking that "was in intent resolution 30s ago and latch acquisition 60s ago" was actually more useful than "was in intent resolution at " since the latter is only meaningful to me, a human, when I compare that clock time the request time and figure out "oh, it was in intent resolution a minute before it was in the iterator? wow that's a long time"

I suppose you could argue a rendering step should translate moments in time to the durations between them for me, but I don't I was hoping to have the messages be useful without depending on too much additional post-processing?

---

pkg/util/tracing/tracingpb/recorded_span.proto line 184 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

nit: I vote we stay away from these comments. Reserving old ids I think is the common practice.

Disagree on this one: these comments should be considered best practice in all proto messages, even if you're never deleted and reserved a field.

These comments aren't about avoiding reuse of old IDs -- that, as you say, is correctly done with the reserved keyword; this is about making it a constant time operation to find the next ID to use for a new field, since fields are (correctly) not required to be in ID order (and indeed should be grouped and ordered by conceptual/purpose adjacency). Sure, in a 4 field message it is easy enough to scan the 4 fields and take the max ID in your head, but that becomes incredibly tedious in larger messages (just try finding the correct next ID for a catalog Descriptor for example), so for consistency we should just make a habit of always including them.

[andreimatei]

feel free to merge at will

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @adityamaru and @dt)

---

pkg/util/tracing/tracingpb/recorded_span.proto line 183 at r6 (raw file):

I suppose you could argue a rendering step should translate moments in time to the durations between them for me

That's indeed what I would argue.
Not a big deal, but making this proto more stand-alone seems like a good idea to me. The sharing stuff in this proto is not meaningful on its own, but still.

[dt]

feel free to merge at will

The one thing on which I was going to wait for an explicit ack, since it was a significant (maybe) departure from the code as last LGTM'ed, is the switch to iterate snaps forward instead of backwards so they're recorded in oldest-to-newest order. It is iterating all up-to-20 so seems fine but figured I'd provide an opportunity to object.

[dt]

Well, this is green so I'm going to avail myself of that permission to merge any time and if we decide we want to change anything I'm happy to hop in with a follow-up.

Thanks for all the patient reviews!

bors r=andreimatei

[craig]

Build succeeded:

• Bazel Essential CI (Cockroach)