tracing: aggregate OperationMetadata on span Finish()

[adityamaru]

This change adds a ChildrenMetadata map to crdbspan that is a
mapping from operation to the operations' aggregated metadata. This
map is updated whenever a child of the crdbSpan finishes, with metadata
from all spans in the finishing childs' Recording. The map is therefore
a bucketed view of all the operations being traced by a span.

The motivation for this change is to surface more metadata about the
suboperations being traced in a spans' Recording. This could in turn provide
more o11y into why a job is slow/stuck, or where the performance of a
distributed operation is bottlenecked.

As part of a span Finish()ing, the span fetches its Recording with the spans'
configured verbosity. Prior to this change the recording would then be
processed as follows:

Verbose Recording

In the case of Verbose recording the spans in the recording are added to the parents'
finishedChildren slice provided we have not exceeded the maximum number of
children a parent can track.

Structured Recording

In the case of a Structured recording, only the StructuredEvents from the spans in
the recording are copied into the parent.

With this change, in both the Verbose and Structured recording mode, a finishing span
is also responsible for rolling up the OperationMetadata of all the spans in its
recording. This involves updating the parents' childrenMetadata mapping with:

1. an entry for the finishing span.
2. an entry for each of the finishing spans' Finish()ed children.
3. an entry for each of the finishing spans' open children, and their children recursively

The logic for 2) and 3) is subsumed in the method responsible for getting
the finishing spans' recording. Notably, GetRecording(...) for both Structured and Verbose
recordings, populate the root of the recording with OperationMetadata of all
finished and open children in the recording.

As an example when we are done finishing child:

parent
  child (finished_C: 4s, finished_D: 3s)
    open_A (finished_B: 1s)
      finished_B
    finished_C (finished_D: 3s)
      finished_D

We'd expect parent to have:
{child: 10s, finished_C: 4s, finished_D: 3s, open_A: 3s, finished_B: 1s}

Given that Finish()ing a child, and importing a remote recording into a span
share the same code path, the above semantics also apply to a remote recording
being imported into a parent span.

Fixes: #80391

Release note: None

[cockroach-teamcity]

This change is 

[adityamaru]

I'd review #81020 first, and then I'll rebase this on top of that.

[andreimatei]

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

---

-- commits line 15 at r3:
"its" what?

---

pkg/util/tracing/crdbspan.go line 128 at r3 (raw file):

	// children in its Recording. childrenMetadata therefore provides a bucketed
	// view of the various operations that are being traced as part of a span.
	childrenMetadata map[string]tracingpb.RecordedSpan_OperationMetadata

does this belong in recording? (i.e., it's only populated when the span is recording, right?)

---

pkg/util/tracing/crdbspan.go line 543 at r3 (raw file):

		//       finished_D
		//
		// We'd expect `parent` to have:

s/we'd expect parent to have/parent will have...

---

pkg/util/tracing/crdbspan.go line 547 at r3 (raw file):

		rootChild := childRecording[0]
		// Record the finished rootChilds' metadata.
		s.mu.childrenMetadata[rootChild.Operation] = s.mu.childrenMetadata[rootChild.Operation].Combine(

Instead of all this, I think it'd be better if recordings always included the ChildrenMetadata. Have you considered having GetRecording() do all this aggregation?

---

pkg/util/tracing/crdbspan.go line 555 at r3 (raw file):

		// Record the metadata of rootChilds' finished children.
		//
		// ChildrenMetadata was populated in GetRecording(...) with rootChilds'

I think this comment lies. GetRecording() doesn't seem to have a role here, does it?

---

pkg/util/tracing/tracingpb/recorded_span.proto line 112 at r2 (raw file):

  reserved 5,10,11;

  // Next ID: 19

nit: I don't see this elsewhere around here. I don't think it's necessary.

[adityamaru]

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

---

pkg/util/tracing/crdbspan.go line 547 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Instead of all this, I think it'd be better if recordings always included the ChildrenMetadata. Have you considered having GetRecording() do all this aggregation?

Every tracingpb.RecordedSpan in a Recording will always have its ChildrenMetadata populated in GetRecording() via the call to getRecordingNoChildrenLocked. This represents the spans' Finish()ed children. When the span is finishing we need to do more than just that:

1. We need to create an entry for the finishing span itself, which is what we are doing here.
2. We need to recurse on the finishing spans' open children and create entries for them and their children.

I don't think it makes sense to do 1) in GetRecording because I do not expect the span whose recording I am getting to be part of the ChildrenMetadata map I am populating in the recording. That is why we do it here when we are finishing the span and updating its parent.

2. is done during GetRecording for Structured because of the fact that we only return 1 tracingpb.RecordedSpan. I'm not convinced it makes sense to do it in the case of GetRecording for Verbose since we do return all tracingpb.RecordedSpans in the Recording, so we can do the recursion on render/finish. This seems more in line with our definition of the two modes?

---

pkg/util/tracing/crdbspan.go line 555 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think this comment lies. GetRecording() doesn't seem to have a role here, does it?

getRecordingNoChildrenLocked which is called from GetRecording in the Verbose mode is responsible for populating ChildrenMetadata in each tracingpb.RecordedSpan. It is populated with all the Finish()ed children of the span at the time the recording is pulled.

[adityamaru]

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

---

-- commits line 15 at r3:

Previously, andreimatei (Andrei Matei) wrote…

"its" what?

its Recording - fixed

---

pkg/util/tracing/crdbspan.go line 128 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

does this belong in recording? (i.e., it's only populated when the span is recording, right?)

Done.

---

pkg/util/tracing/crdbspan.go line 543 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/we'd expect parent to have/parent will have...

Done.

[andreimatei]

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

---

pkg/util/tracing/crdbspan.go line 547 at r3 (raw file):

I don't think it makes sense to do 1) in GetRecording because I do not expect the span whose recording I am getting to be part of the ChildrenMetadata map I am populating in the recording. That is why we do it here when we are finishing the span and updating its parent.

This part makes sense.

2 is done during GetRecording for Structured because of the fact that we only return 1 tracingpb.RecordedSpan. I'm not convinced it makes sense to do it in the case of GetRecording for Verbose since we do return all tracingpb.RecordedSpans in the Recording, so we can do the recursion on render/finish. This seems more in line with our definition of the two modes?

I think verbose and structured recordings should behave the same with respect to returning the childrenMetadata; I think they should both return it, and they should both include the stats about open children. Even though one can recurse through a verbose recording and compute whatever they want, I think it'd be very useful that this standardized childrenMeta is always there (by the argument that a verbose recording can be processed by the caller, you wouldn't need to include the stats of the finished spans either). Otherwise, I'm pretty sure the difference in this respect between structured recordings and verbose recordings is going to surprise us every time.
Also, I think the distinction you're trying to draw about open children and finished children is inconsistent. In a structure like the following:

root
   c1
     c11
  c2 

if c1 finishes, and I collect root's (verbose) recording, I get: {c11, unfinished:true}, {c1}. So, I get info about some unfinished children (c11) but not others (c2). That's surprising!

WDYT?

Not to mention that, if we make verbose recordings include the stats for open children, the code in this function should be uniform regardless of the recording mode. As it stands, there's too much code :P. I think we should aim for this code to only need to look at rootChild and not the other spans.

---

pkg/util/tracing/crdbspan.go line 555 at r3 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

getRecordingNoChildrenLocked which is called from GetRecording in the Verbose mode is responsible for populating ChildrenMetadata in each tracingpb.RecordedSpan. It is populated with all the Finish()ed children of the span at the time the recording is pulled.

I see.

---

pkg/util/tracing/crdbspan.go line 178 at r4 (raw file):

	// children in its Recording. childrenMetadata therefore provides a bucketed
	// view of the various operations that are being traced as part of a span.
	childrenMetadata map[string]tracingpb.RecordedSpan_OperationMetadata

since we're using this proto in code that otherwise does not have much to do with RecordedSpan, let's make the OperationMetadata be defined as a top-level message, instead of a sub-message inside of RecordedSpan

---

pkg/util/tracing/crdbspan.go line 573 at r4 (raw file):

		// been flattened into `childRecording` by `GetRecording(...)`
		for _, rec := range childRecording[1:] {
			if !rec.Finished {

see, I think this if !rec.Finished is really ugly. Ain't nobody gonna understand what's going on.

[adityamaru]

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

---

pkg/util/tracing/crdbspan.go line 547 at r3 (raw file):

That's surprising!

Indeed, you're right. It makes sense to push this logic into GetRecording for both Verbose and Structured. I've changed the PR to reflect this.

---

pkg/util/tracing/crdbspan.go line 555 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I see.

Done.

---

pkg/util/tracing/crdbspan.go line 178 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

since we're using this proto in code that otherwise does not have much to do with RecordedSpan, let's make the OperationMetadata be defined as a top-level message, instead of a sub-message inside of RecordedSpan

Done.

---

pkg/util/tracing/crdbspan.go line 573 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

see, I think this if !rec.Finished is really ugly. Ain't nobody gonna understand what's going on.

agreed, moved this logic to GetRecording.

[andreimatei]

Consider including the new stats in Recording.String(). If it turns out to be overwhelming, we can back it out, or trim it, or something. But I'd be curious to see how the full thing looks for starters.

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

[adityamaru]

I'll do this yup, I was going to work on making this usable from the built-in that pulls a recording as the next PR. As part of that I'll also stick this in the stringer.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @andreimatei, @benbardin, and @stevendanna)

---

pkg/util/tracing/crdbspan.go line 492 at r5 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

nit: join these two paragraphs into one, to make it clear that they're in contrast to one another. Otherwise, I don't think the first one will mean much to readers.

I think you were referring to the two comments. I've deleted one of them since it wasn't really adding much.

---

pkg/util/tracing/crdbspan.go line 496 at r5 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Looks better!

Done.

---

pkg/util/tracing/crdbspan.go line 430 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Instead of taking this lock, I think it'd be better to take the data you need from openChildRecording[0]. It's all there, right?

Done.

---

pkg/util/tracing/crdbspan.go line 443 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

can't this be

childrenMetadata[opName] = childrenMetadata[opName].Combine(metadata)

?

If so, consider extracting this loop into a function, called perhaps RollupChildrenMeta(childrenMeta, openChildRecording[0].ChildrenMetadata), cause you have the same loop elsewhere and I think it'd benefit from a name.

Done.

---

pkg/util/tracing/crdbspan.go line 457 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/from s' children/from s' open children

I scratched my head for a bit trying to understand if the Combine calls below are necessary

childrenMetadata contains entries from both open and finished children, so here we're just rolling up all those entries into the root of the recording.

---

pkg/util/tracing/crdbspan.go line 495 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

instead of adding this new includeRootStructuredEvents param, I think I'd rather keep getChildrenStructuredEventsRecursivelyLocked (and rename it back to getStructuredEventsRecursivelyLocked), always including the root, and assign res.StructuredRecords = buffer below. And then the whole bit below about managing the space in res.StructuredRecords goes away. I think the only thing that we lose is wasted work copying the structured events in getRecordingNoChildrenLocked, but I don't think that's a big deal.

I'd write this as

res := s.getRecordingNoChildrenLocked(
	tracingpb.RecordingStructured,
	false, // finishing - since we're only asking for the structured recording, the argument doesn't matter
)
res.StructuredRecords  = s.getStructuredEventsRecursivelyLocked(res.StructuredRecords[:], includeDetachedChildren)

hmm res.StructuredRecords = s.getStructuredEventsRecursivelyLocked(res.StructuredRecords[:], includeDetachedChildren) would double count the structured records in the root won't it? res.StructuredRecords[:] would already have the events for the root, and then we'd again append the roots' events to that slice.

I've changed it to take in a buffer instead and then deleted the entire block around memory management below.

[andreimatei]

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

---

pkg/util/tracing/crdbspan.go line 457 at r6 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

childrenMetadata contains entries from both open and finished children, so here we're just rolling up all those entries into the root of the recording.

oh so then can we replace this whole block with rootSpan.ChildrenMetada = childrenMetadata ?

---

pkg/util/tracing/crdbspan.go line 495 at r6 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

hmm res.StructuredRecords = s.getStructuredEventsRecursivelyLocked(res.StructuredRecords[:], includeDetachedChildren) would double count the structured records in the root won't it? res.StructuredRecords[:] would already have the events for the root, and then we'd again append the roots' events to that slice.

I've changed it to take in a buffer instead and then deleted the entire block around memory management below.

ugh, sorry, I meant res.StructuredRecords[:0]. I think you can use that to avoid allocating buffer.

---

pkg/util/tracing/crdbspan.go line 411 at r7 (raw file):

	}

	s.mu.Lock()

nit: put everything until the unlock in a { } block for visibility, now that the block has gotten pretty large.

---

pkg/util/tracing/crdbspan.go line 480 at r7 (raw file):

	defer s.mu.Unlock()

	// Fetch s' recording without including its children.

nit: this comment doesn't add anything to the function name

---

pkg/util/tracing/crdbspan.go line 494 at r7 (raw file):

	// open.
	childrenMetadata := make(map[string]tracingpb.OperationMetadata)
	s.getChildrenMetadataRecursivelyLocked(childrenMetadata,

can we pass in res.ChildrenMetadata here, and get rid of childrenMetadata

[adityamaru]

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

---

pkg/util/tracing/crdbspan.go line 457 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

oh so then can we replace this whole block with rootSpan.ChildrenMetada = childrenMetadata ?

Done.

---

pkg/util/tracing/crdbspan.go line 495 at r6 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

ugh, sorry, I meant res.StructuredRecords[:0]. I think you can use that to avoid allocating buffer.

Done.

---

pkg/util/tracing/crdbspan.go line 494 at r7 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

can we pass in res.ChildrenMetadata here, and get rid of childrenMetadata

Done.

[adityamaru]

I'm seeing the CI failure on other builds in staging too https://teamcity.cockroachdb.com/viewLog.html?buildId=5547912&tab=buildResultsDiv&buildTypeId=Cockroach_UnitTests_CheckGeneratedCode.

I'll bring it up with whoever owns web UI tests but I don't think it is related to this diff.

TFTR!

bors r=andreimatei

[craig]

Build failed:

• GitHub CI (Cockroach)

[adityamaru]

bors r=andreimatei

[craig]

Build failed:

• GitHub CI (Cockroach)

[adityamaru]

Now its TestDockerCLI acting up 😢 , let's try again.

bors r=andreimatei

[craig]

Build failed:

• GitHub CI (Cockroach)

[adityamaru]

Another flake, this time on #83253

bors r=andreimatei

[craig]

Build succeeded:

• GitHub CI (Cockroach)