util/tracing: fix String() for recordings of child spans #50914

andreimatei · 2020-07-02T03:12:33Z

The String() method wasn't working for recordings of non-root spans,
because it was looking for a root span (parent id = 0). A recording for
a span that had a parent doesn't have a root span. Things mostly worked
in practice, though, as children of no-op spans had a parent id = 0, so
they looked like roots.

This patch switches to assuming that the first span in the recording is
the "root of that recording".

Release note (bug fix): Fixed a bug causing the raw trace file collected
inside a statement diagnostics bundle to be sometimes empty when the
cluster setting sql.trace.txn.enable_threshold was in use.

cockroach-teamcity · 2020-07-02T03:12:41Z

This change is

andreimatei · 2020-07-02T03:37:04Z

@ajwerner look at the first commit pls
@RichardJCai look at the second pls

RaduBerinde

(only looked at second and third commit). Pretty cool, making trees of groups was a relatively simple change but drastically improves the semantics.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @ajwerner, @andreimatei, @RaduBerinde, and @RichardJCai)

pkg/util/tracing/tracer.go, line 422 at r2 (raw file):

//
// If separateRecording is false (the usual case), then the child span will be
// part of the same recording. If separateRecording is true and the parent span

"part of the same recording" needs more qualification. It's the same recording but not really, because if you do GetRecording on the child, you only get that portion of the recording.

pkg/util/tracing/tracer.go, line 423 at r2 (raw file):

// If separateRecording is false (the usual case), then the child span will be
// part of the same recording. If separateRecording is true and the parent span
// is recording, we start a new recording for the child span. This is useful

But now we can extract the child recording regardless.. So do we still need this flag? It seems like now the only difference between having a separate recording is whether the parent recording includes the child spans (and I don't see why we wouldn't want to include them always).

pkg/util/tracing/tracer_span.go, line 173 at r2 (raw file):

	s.mu.Lock()
	atomic.StoreInt32(&s.recording, 1)
	recGroup := newSpanGroup(s)

It feels like we shouldn't need to have a group per span; we only need to create a new "node" in this tree when we start a span with separate recording. Wouldn't it be equivalent (but save a lot of allocations) to use the parent group like before, unless it's a separate recording (and only in that case create a new group)?

I guess this would be different when we try to get the recording of a child that did not request a separate recording (we'd get the entire recording like today). I'm not sure if this matters?

pkg/util/tracing/tracer_span.go, line 879 at r2 (raw file):

	// subgroups are the groups of sp's children (namely, the children created
	// after the recording started).
	subgroups []*spanGroup

[nit] maybe childGroups is a better name?

pkg/util/tracing/tracer_span.go, line 916 at r2 (raw file):

	result := Recording{ss.sp.getRecording()}
	for _, subGroup := range ss.subgroups {
		result = append(result, subGroup.getSpans()...)

This recursive call under a lock feels sketchy (though of course it should work since it's all a tree, and there is no other piece of code that takes multiple spanGroup locks at the same time). It might be nicer to just put the ss.subgroups slice in a variable and release the lock before the recursive calls (we can do that because we never modify the slice elements, we just append).

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

	tags: sb=1
`))
	fmt.Printf(childRec.String())

is this Printf leftover?

ajwerner

First commit

Reviewed 1 of 1 files at r1.
Reviewable status: complete! 2 of 0 LGTMs obtained (waiting on @ajwerner, @andreimatei, and @RichardJCai)

RichardJCai

LGTM, one tiny comment typo

RichardJCai · 2020-07-02T14:38:46Z

pkg/util/tracing/tracer_span.go

-	// as soon as it is opened; the first element is the span passed to
-	// StartRecording().
-	spans []*span
+	// sp if the span that this group corresponds to.


Nit: typo here, if should be is

andreimatei

Radu, I've reworked this. PTAL.

Reviewable status: complete! 2 of 0 LGTMs obtained (waiting on @RaduBerinde and @RichardJCai)

pkg/util/tracing/tracer.go, line 422 at r2 (raw file):

Previously, RaduBerinde wrote…

"part of the same recording" needs more qualification. It's the same recording but not really, because if you do GetRecording on the child, you only get that portion of the recording.

I got rid of that sentence

pkg/util/tracing/tracer.go, line 423 at r2 (raw file):

Previously, RaduBerinde wrote…

But now we can extract the child recording regardless.. So do we still need this flag? It seems like now the only difference between having a separate recording is whether the parent recording includes the child spans (and I don't see why we wouldn't want to include them always).

added another sentence explaining more

pkg/util/tracing/tracer_span.go, line 173 at r2 (raw file):

Previously, RaduBerinde wrote…

It feels like we shouldn't need to have a group per span; we only need to create a new "node" in this tree when we start a span with separate recording. Wouldn't it be equivalent (but save a lot of allocations) to use the parent group like before, unless it's a separate recording (and only in that case create a new group)?

I guess this would be different when we try to get the recording of a child that did not request a separate recording (we'd get the entire recording like today). I'm not sure if this matters?

n/a

pkg/util/tracing/tracer_span.go, line 875 at r2 (raw file):

Previously, RichardJCai (Richard Cai) wrote…

Nit: typo here, if should be is

n/a

pkg/util/tracing/tracer_span.go, line 879 at r2 (raw file):

Previously, RaduBerinde wrote…

[nit] maybe childGroups is a better name?

n/a

pkg/util/tracing/tracer_span.go, line 916 at r2 (raw file):

Previously, RaduBerinde wrote…

This recursive call under a lock feels sketchy (though of course it should work since it's all a tree, and there is no other piece of code that takes multiple spanGroup locks at the same time). It might be nicer to just put the ss.subgroups slice in a variable and release the lock before the recursive calls (we can do that because we never modify the slice elements, we just append).

done in the new place

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

Previously, RaduBerinde wrote…

is this Printf leftover?

yup, thanks

RaduBerinde

Very nice!

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

pkg/util/tracing/tracer_span.go, line 142 at r5 (raw file):

			recordingType RecordingType
			recordedLogs  []opentracing.LogRecord
			children      []*span

Could use a comment - this is the list of all child spans that were started from this span, after the recording was started, right?

pkg/util/tracing/tracer_span.go, line 193 at r5 (raw file):

		s.setBaggageItemLocked(Snowball, "1")
	}
	// Clear any previously recorded logs.

Not sure why we need this, but if we're doing it, should we also clear the remoteSpans?

pkg/util/tracing/tracer_span.go, line 214 at r5 (raw file):

	}

	sp := os.(*span)

[nit] if sp := ..; !isRecording{} { enableRecording() } (you can move the comment above the if)

pkg/util/tracing/tracer_span.go, line 278 at r5 (raw file):

	result := make(Recording, 0, 1+len(s.mu.recording.children)+len(s.mu.recording.remoteSpans))
	// Copy the children so we can process them without the lock.
	children := make([]*span, len(s.mu.recording.children))

[nit] children := append([]*span(nil), s.mu.recording.children...) I think you can also just use the slice, because we're never modifying existing slice elements.

andreimatei

TFTR!

bors r+

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

pkg/util/tracing/tracer_span.go, line 142 at r5 (raw file):

Previously, RaduBerinde wrote…

Could use a comment - this is the list of all child spans that were started from this span, after the recording was started, right?

done

pkg/util/tracing/tracer_span.go, line 193 at r5 (raw file):

Previously, RaduBerinde wrote…

Not sure why we need this, but if we're doing it, should we also clear the remoteSpans?

Yes - I've extended it to clear everything. It is needed; I've added a comment explaining why.

pkg/util/tracing/tracer_span.go, line 214 at r5 (raw file):

Previously, RaduBerinde wrote…

[nit] if sp := ..; !isRecording{} { enableRecording() } (you can move the comment above the if)

done

pkg/util/tracing/tracer_span.go, line 278 at r5 (raw file):

Previously, RaduBerinde wrote…

[nit] children := append([]*span(nil), s.mu.recording.children...) I think you can also just use the slice, because we're never modifying existing slice elements.

there was a bunch of nonsense around here, thanks

craig · 2020-07-07T23:12:55Z

Build failed

GitHub CI (Cockroach)

andreimatei

bors r+

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

craig · 2020-07-08T00:52:49Z

Build failed

GitHub CI (Cockroach)

This index drop test was a bit out there. It was tracing a transaction through SQL, and then hackily getting its hands on the respective trace from KV. In doing that, it was relying on GetRecording(sp) to return the recoding of one of sp's ancestors. That behavior is about to change. This test doesn't need tracing to do what it wants, and it's cleaner without it. Release note: None

Before this patch, the behavior of a recording inside a recording was no good because of shortcuts taken in the implementation of the recording mechanism. Before, there was really no concept of a recording inside a recording; a child's recording was the same as the parent's. So, if a child had been created in a parent that was already recording, and then you tried to get the recording from the child, you'd get the parent's recording. To make it more confusing, if you explicitly started a child's recording, then the child would get a separate recording indeed, but the parent's recording would not contain the child's (for extra extra confusion, the parent's recording would actually the log messages from the child spans, but not any info on grandchildren). This was a problem for SQL tracing, which has different features that enable recording at different levels - full txn recording vs single-stmt recording. When both were enabled, the interaction buggy. This patch reworks the code around recording traces. We do away with the spanGroup; instead recording spans now keep track of their children internally. We get the flexibility of reading a child's recording from inside a parent's recording. The structure keeping track of recorded info (spanGroup) is now hierarchical, with each span getting its own group. As a consequence, this patch fixes the recent Executor testing knob WithStatementTrace, which was failing to include sub-queries ran using the InternalExecutor in the recordings it was collecting. As such, it was under-counting KV requests in the ddl_analysis test. Those counts have been corrected (sadly, upwards). Release note: None

The String() method wasn't working for recordings of non-root spans, because it was looking for a root span (parent id = 0). A recording for a span that had a parent doesn't have a root span. Things mostly worked in practice, though, as children of no-op spans had a parent id = 0, so they looked like roots. This patch switches to assuming that the first span in the recording is the "root of that recording". Release note (bug fix): Fixed a bug causing the raw trace file collected inside a statement diagnostics bundle to be sometimes empty when the cluster setting sql.trace.txn.enable_threshold was in use.

andreimatei · 2020-07-08T18:39:49Z

bors r+

craig · 2020-07-08T20:21:13Z

Build succeeded

GitHub CI (Cockroach)

`WithSeparateRecording` set up a Span to *not* share its recording with its parent. This was necessary before cockroachdb#50914 as parents would also show up in children's recording, and SQL SpanStats want to set up spans only for the purpose of populating them with the stats (and want to avoid pulling a possibly giant recording of the parent out with it). PR cockroachdb#50914 introduced the unidirectional transitivity we have today: a parent's recording will recurse into the child, but not vice versa. This means that the existing uses of `WithSeparateRecording` were no longer useful; all they were doing was to hide information from the parent. In fact, they are counterproductive, as they prevent the full recording to become available at the root span, which is not an issue today since the only thing missing are SpanStats, but with always-on tracing we'd possibly silently drop metadata. Release note: None

andreimatei requested a review from RaduBerinde July 2, 2020 03:12

andreimatei requested review from RichardJCai and ajwerner July 2, 2020 03:33

RaduBerinde approved these changes Jul 2, 2020

View reviewed changes

ajwerner approved these changes Jul 2, 2020

View reviewed changes

RichardJCai approved these changes Jul 2, 2020

View reviewed changes

andreimatei force-pushed the tracing.child-recording branch from 98ffba7 to ca24aa6 Compare July 2, 2020 20:41

andreimatei commented Jul 2, 2020

View reviewed changes

RaduBerinde reviewed Jul 2, 2020

View reviewed changes

andreimatei force-pushed the tracing.child-recording branch from ca24aa6 to b496d85 Compare July 7, 2020 22:10

andreimatei commented Jul 7, 2020

View reviewed changes

andreimatei force-pushed the tracing.child-recording branch from b496d85 to 8e52bfd Compare July 8, 2020 00:10

andreimatei commented Jul 8, 2020

View reviewed changes

andreimatei added 3 commits July 8, 2020 11:34

andreimatei force-pushed the tracing.child-recording branch from 8e52bfd to 8969acb Compare July 8, 2020 15:38

craig bot merged commit be357ff into cockroachdb:master Jul 8, 2020

andreimatei deleted the tracing.child-recording branch July 9, 2020 16:46

tbg mentioned this pull request Nov 4, 2020

tracing: remove WithSeparateRecording #56276

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

util/tracing: fix String() for recordings of child spans #50914

util/tracing: fix String() for recordings of child spans #50914

andreimatei commented Jul 2, 2020

cockroach-teamcity commented Jul 2, 2020

andreimatei commented Jul 2, 2020

RaduBerinde left a comment

ajwerner left a comment

RichardJCai left a comment

RichardJCai Jul 2, 2020

andreimatei left a comment

RaduBerinde left a comment

andreimatei left a comment

craig bot commented Jul 7, 2020

andreimatei left a comment

craig bot commented Jul 8, 2020

andreimatei commented Jul 8, 2020

craig bot commented Jul 8, 2020

util/tracing: fix String() for recordings of child spans #50914

util/tracing: fix String() for recordings of child spans #50914

Conversation

andreimatei commented Jul 2, 2020

cockroach-teamcity commented Jul 2, 2020

andreimatei commented Jul 2, 2020

RaduBerinde left a comment

Choose a reason for hiding this comment

ajwerner left a comment

Choose a reason for hiding this comment

RichardJCai left a comment

Choose a reason for hiding this comment

RichardJCai Jul 2, 2020

Choose a reason for hiding this comment

andreimatei left a comment

Choose a reason for hiding this comment

RaduBerinde left a comment

Choose a reason for hiding this comment

andreimatei left a comment

Choose a reason for hiding this comment

craig bot commented Jul 7, 2020

Build failed

andreimatei left a comment

Choose a reason for hiding this comment

craig bot commented Jul 8, 2020

Build failed

andreimatei commented Jul 8, 2020

craig bot commented Jul 8, 2020

Build succeeded