diff --git a/pkg/kv/kvserver/concurrency/lock_table_waiter.go b/pkg/kv/kvserver/concurrency/lock_table_waiter.go index b60b796775a0..5dcf3453c019 100644 --- a/pkg/kv/kvserver/concurrency/lock_table_waiter.go +++ b/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 } diff --git a/pkg/sql/exec_util.go b/pkg/sql/exec_util.go index 1809d9a788f4..02153cbeab80 100644 --- a/pkg/sql/exec_util.go +++ b/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 diff --git a/pkg/util/tracing/crdbspan.go b/pkg/util/tracing/crdbspan.go index 0ab84dc0ff2a..170ef3d8c95f 100644 --- a/pkg/util/tracing/crdbspan.go +++ b/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) diff --git a/pkg/util/tracing/doc.go b/pkg/util/tracing/doc.go index 99f8c24919ad..9b4a70f87f81 100644 --- a/pkg/util/tracing/doc.go +++ b/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` diff --git a/pkg/util/tracing/span.go b/pkg/util/tracing/span.go index 6c3e399a20df..170c79bcca71 100644 --- a/pkg/util/tracing/span.go +++ b/pkg/util/tracing/span.go @@ -118,17 +118,14 @@ 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")) } @@ -136,15 +133,31 @@ func (s *Span) SetVerbose(to bool) { // 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 diff --git a/pkg/util/tracing/span_test.go b/pkg/util/tracing/span_test.go index 1e1e72104165..d2a8a236879a 100644 --- a/pkg/util/tracing/span_test.go +++ b/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) diff --git a/pkg/util/tracing/tracingpb/recorded_span.go b/pkg/util/tracing/tracingpb/recorded_span.go index 32640cbb38c8..04db86974e6d 100644 --- a/pkg/util/tracing/tracingpb/recorded_span.go +++ b/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 {