[wip] tracing: extract side-effect that clear span recordings

pkg/kv/kvserver/concurrency/lock_table_waiter.go

@@ -689,11 +689,11 @@ func (h *contentionEventHelper) emit() {
 	}
 	h.ev.Duration = timeutil.Since(h.tBegin)
 	if h.onEvent != nil {
-		// NB: this is intentionally above the call to LogStructured so that
+		// NB: this is intentionally above the call to RecordStructured so that
 		// this interceptor gets to mutate the event (used for test determinism).
 		h.onEvent(h.ev)
 	}
-	h.sp.LogStructured(h.ev)
+	h.sp.RecordStructured(h.ev)
 	h.ev = nil
 }
 

pkg/sql/exec_util.go

@@ -1552,6 +1552,7 @@ func (st *SessionTracing) StartTracing(
 		if sp == nil {
 			return errors.Errorf("no txn span for SessionTracing")
 		}
+		sp.ResetRecording()
 		sp.SetVerbose(true)
 		st.firstTxnSpan = sp
 	}
@@ -1571,6 +1572,7 @@ func (st *SessionTracing) StartTracing(
 		opName,
 		tracing.WithForceRealSpan(),
 	)
+	sp.ResetRecording()
 	sp.SetVerbose(true)
 	st.connSpan = sp
 

pkg/util/tracing/crdbspan.go

@@ -111,12 +111,6 @@ func (s *crdbSpan) enableRecording(parent *crdbSpan, recType RecordingType) {
 	if recType == RecordingVerbose {
 		s.setBaggageItemLocked(verboseTracingBaggageKey, "1")
 	}
-	// Clear any previously recorded info. This is needed by SQL SessionTracing,
-	// who likes to start and stop recording repeatedly on the same Span, and
-	// collect the (separate) recordings every time.
-	s.mu.recording.recordedLogs = nil
-	s.mu.recording.children = nil
-	s.mu.recording.remoteSpans = nil
 }
 
 func (s *crdbSpan) disableRecording() {
@@ -205,7 +199,7 @@ func (s *crdbSpan) record(msg string) {
 	}
 }
 
-func (s *crdbSpan) logStructured(item Structured) {
+func (s *crdbSpan) recordStructured(item Structured) {
 	s.mu.Lock()
 	defer s.mu.Unlock()
 	s.mu.structured = append(s.mu.structured, item)

pkg/util/tracing/doc.go

@@ -93,9 +93,20 @@
 // [5]: `ForkCtxSpan`. "forking" a Span is the same as creating a new one
 //      with a "follows from" relation.
 // [6]: `crdbSpan`
-// [7]: `Span.SetVerbose`. To understand the specifics of what exactly is
-//      captured in Span recording, when Spans have children that may be either
-//      local or remote, look towards `WithParentAnd{Auto,Manual}Collection`
+// [7]: `Span.SetVerbose`. To understand the specifics of what's captured in
+//      Span recordings, when Spans have children that may be either local or
+//      remote, look towards `WithParentAnd{Auto,Manual}Collection`.
+//      The complexity here stems from how we expect parentSpan.GetRecording()
+//      to behave. If all child spans are created using the AutoCollection
+//      option, grabbing the parent span's recording automatically captures all
+//      child span recordings. This is easy to implement, and doesn't have to
+//      leak outside the tracing package.
+//      For operations that tread RPC boundaries however, we cannot simply
+//      retrieve remote child recordings ourselves. To that end we provide
+//      the ManualCollection option, where the caller is responsible for
+//      capturing the remote child span's recording (`span.GetRecording`),
+//      transferring it over the wire, and importing it into the parent span
+//      (`ImportRemoteSpans`).
 // [8]: `Tracer.{Inject,Extract}`
 // [9]: `SpanMeta`
 // [10]: `{Client,Server}Interceptor`

pkg/util/tracing/span.go

@@ -118,33 +118,46 @@ func (s *Span) IsVerbose() bool {
 // descendants of this Span will do so automatically as well. This does not
 // apply to past derived Spans, which may in fact be noop spans.
 //
-// As a side effect, calls to `SetVerbose(true)` on a span that was not already
-// verbose will reset any past recording stored on this Span.
-//
 // When set to 'false', Record will cede to add data to the recording (though
 // they may still be collected, should the Span have been set up with an
 // auxiliary trace sink). This does not apply to Spans derived from this one
 // when it was verbose.
 func (s *Span) SetVerbose(to bool) {
-	// TODO(tbg): when always-on tracing is firmly established, we can remove the ugly
-	// caveat that SetVerbose(true) is a panic on a noop span because there will be no
-	// noop span.
+	// TODO(tbg): when always-on tracing is firmly established, we can remove
+	// the ugly caveat that SetVerbose(true) is a panic on a noop span because
+	// there will be no noop span.
 	if s.isNoop() {
 		panic(errors.AssertionFailedf("SetVerbose called on NoopSpan; use the WithForceRealSpan option for StartSpan"))
 	}
 	if to {
 		// If we're already recording (perhaps because the parent was recording when
 		// this Span was created), there's nothing to do. Avoid the call to enableRecording
 		// because it would clear the existing recording.
-		recType := RecordingVerbose
-		if recType != s.crdb.recordingType() {
-			s.crdb.enableRecording(nil /* parent */, recType)
+		if s.crdb.recordingType() != RecordingVerbose {
+			s.crdb.enableRecording(nil /* parent */, RecordingVerbose)
 		}
 	} else {
 		s.crdb.disableRecording()
 	}
 }
 
+// ResetRecording will reset any past recording stored on this Span.
+func (s *Span) ResetRecording() {
+	// TODO(irfansharif): Once always-on tracing is the only mode available,
+	// we'll no longer have noop spans, and we can remove this caveat.
+	if s.isNoop() {
+		panic(errors.AssertionFailedf("ResetRecording called on NoopSpan; use the WithForceRealSpan option for StartSpan"))
+	}
+	// Clear any previously recorded info. This is needed by SQL SessionTracing,
+	// who likes to start and stop recording repeatedly on the same Span, and
+	// collect the (separate) recordings every time.
+	s.crdb.mu.Lock()
+	s.crdb.mu.recording.recordedLogs = nil
+	s.crdb.mu.recording.children = nil
+	s.crdb.mu.recording.remoteSpans = nil
+	s.crdb.mu.Unlock()
+}
+
 // GetRecording retrieves the current recording, if the Span has recording
 // enabled. This can be called while spans that are part of the recording are
 // still open; it can run concurrently with operations on those spans.
@@ -193,14 +206,14 @@ type SpanStats interface {
 // SetSpanStats sets the stats on a Span. stats.Stats() will also be added to
 // the Span tags.
 //
-// This is deprecated. Use LogStructured instead.
+// This is deprecated. Use RecordStructured instead.
 //
 // TODO(tbg): remove this in the 21.2 cycle.
 func (s *Span) SetSpanStats(stats SpanStats) {
 	if s.isNoop() {
 		return
 	}
-	s.LogStructured(stats)
+	s.RecordStructured(stats)
 	s.crdb.mu.Lock()
 	s.crdb.mu.stats = stats
 	for name, value := range stats.StatsTags() {
@@ -320,22 +333,23 @@ func (s *Span) setTagInner(key string, value interface{}, locked bool) *Span {
 }
 
 // Structured is an opaque protobuf that can be attached to a trace via
-// `Span.LogStructured`. This is the only kind of data a Span carries when
+// `Span.RecordStructured`. This is the only kind of data a Span carries when
 // `trace.mode = background`.
 type Structured interface {
 	protoutil.Message
 }
 
-// LogStructured adds a Structured payload to the Span. It will be added to the
-// recording even if the Span is not verbose; however it will be discarded if
-// the underlying Span has been optimized out (i.e. is a noop span).
+// RecordStructured provides a way to record a Structured payload into the Span.
+// It will be added to the recording even if the Span is not verbose; however it
+// will be discarded if the underlying Span has been optimized out (i.e. is a
+// noop span).
 //
-// The caller must not mutate the item once LogStructured has been called.
-func (s *Span) LogStructured(item Structured) {
+// The caller must not mutate the item once RecordStructured has been called.
+func (s *Span) RecordStructured(item Structured) {
 	if s.isNoop() {
 		return
 	}
-	s.crdb.logStructured(item)
+	s.crdb.recordStructured(item)
 	if s.hasVerboseSink() {
 		// NB: TrimSpace avoids the trailing whitespace
 		// generated by the protobuf stringers.
@@ -346,8 +360,8 @@ func (s *Span) LogStructured(item Structured) {
 // Record provides a way to record free-form text into verbose spans.
 //
 // TODO(irfansharif): We don't currently have redactability with trace
-// recordings (both here, and using LogStructured above). We'll want to do this
-// soon.
+// recordings (both here, and using RecordStructured above). We'll want to do
+// this soon.
 func (s *Span) Record(msg string) {
 	if !s.hasVerboseSink() {
 		return

pkg/util/tracing/span_test.go

@@ -187,7 +187,7 @@ func TestSpan_LogStructured(t *testing.T) {
 	sp := tr.StartSpan("root", WithForceRealSpan())
 	defer sp.Finish()
 
-	sp.LogStructured(&types.Int32Value{Value: 4})
+	sp.RecordStructured(&types.Int32Value{Value: 4})
 	rec := sp.GetRecording()
 	require.Len(t, rec, 1)
 	require.Len(t, rec[0].InternalStructured, 1)
@@ -206,7 +206,7 @@ func TestNonVerboseChildSpanRegisteredWithParent(t *testing.T) {
 	defer ch.Finish()
 	require.Len(t, sp.crdb.mu.recording.children, 1)
 	require.Equal(t, ch.crdb, sp.crdb.mu.recording.children[0])
-	ch.LogStructured(&types.Int32Value{Value: 5})
+	ch.RecordStructured(&types.Int32Value{Value: 5})
 	// Check that the child span (incl its payload) is in the recording.
 	rec := sp.GetRecording()
 	require.Len(t, rec, 2)

pkg/util/tracing/tracingpb/recorded_span.go

@@ -31,7 +31,7 @@ func (s *RecordedSpan) String() string {
 	return sb.String()
 }
 
-// Structured visits the data passed to LogStructured for the Span from which
+// Structured visits the data passed to RecordStructured for the Span from which
 // the RecordedSpan was created.
 func (s *RecordedSpan) Structured(visit func(*types.Any)) {
 	if s.DeprecatedStats != nil {