tracing: elide tags from recording if not verbose

pkg/settings/cluster/cluster_settings.go

@@ -121,9 +121,19 @@ func MakeClusterSettings() *Settings {
 	sv.Init(s.Version)
 
 	s.Tracer = tracing.NewTracer()
+	isActive := int32(0) // atomic
 	s.Tracer.TracingVerbosityIndependentSemanticsIsActive = func() bool {
-		return s.Version.IsActive(context.Background(),
-			clusterversion.TracingVerbosityIndependentSemantics)
+		// IsActive is mildly expensive for the hot path this function
+		// is in, so cache a return value of true.
+		if atomic.LoadInt32(&isActive) != 0 {
+			return true
+		}
+		if s.Version.IsActive(context.Background(),
+			clusterversion.TracingVerbosityIndependentSemantics) {
+			atomic.StoreInt32(&isActive, 1)
+			return true
+		}
+		return false
 	}
 	s.Tracer.Configure(sv)
 

pkg/util/tracing/crdbspan.go

@@ -142,7 +142,7 @@ func (s *crdbSpan) disableRecording() {
 	}
 }
 
-func (s *crdbSpan) getRecording(everyoneIsV211 bool) Recording {
+func (s *crdbSpan) getRecording(everyoneIsV211 bool, wantTags bool) Recording {
 	if s == nil {
 		return nil // noop span
 	}
@@ -168,12 +168,12 @@ func (s *crdbSpan) getRecording(everyoneIsV211 bool) Recording {
 	result := make(Recording, 0, 1+len(s.mu.recording.children)+len(s.mu.recording.remoteSpans))
 	// Shallow-copy the children so we can process them without the lock.
 	children := s.mu.recording.children
-	result = append(result, s.getRecordingLocked())
+	result = append(result, s.getRecordingLocked(wantTags))
 	result = append(result, s.mu.recording.remoteSpans...)
 	s.mu.Unlock()
 
 	for _, child := range children {
-		result = append(result, child.getRecording(everyoneIsV211)...)
+		result = append(result, child.getRecording(everyoneIsV211, wantTags)...)
 	}
 
 	// Sort the spans by StartTime, except the first Span (the root of this
@@ -257,7 +257,10 @@ func (s *crdbSpan) setBaggageItemLocked(restrictedKey, value string) {
 
 // getRecordingLocked returns the Span's recording. This does not include
 // children.
-func (s *crdbSpan) getRecordingLocked() tracingpb.RecordedSpan {
+//
+// When wantTags is false, no tags will be added. This is a performance
+// optimization as stringifying the tag values can be expensive.
+func (s *crdbSpan) getRecordingLocked(wantTags bool) tracingpb.RecordedSpan {
 	rs := tracingpb.RecordedSpan{
 		TraceID:      s.traceID,
 		SpanID:       s.spanID,
@@ -285,13 +288,13 @@ func (s *crdbSpan) getRecordingLocked() tracingpb.RecordedSpan {
 		rs.Tags[k] = v
 	}
 
-	// When nobody is configured to see our spans, skip some allocations
-	// related to Span UX improvements.
-	if s.mu.duration == -1 {
-		addTag("_unfinished", "1")
-	}
-	if s.mu.recording.recordingType.load() == RecordingVerbose {
-		addTag("_verbose", "1")
+	if wantTags {
+		if s.mu.duration == -1 {
+			addTag("_unfinished", "1")
+		}
+		if s.mu.recording.recordingType.load() == RecordingVerbose {
+			addTag("_verbose", "1")
+		}
 	}
 
 	if s.mu.stats != nil {
@@ -322,17 +325,20 @@ func (s *crdbSpan) getRecordingLocked() tracingpb.RecordedSpan {
 			rs.Baggage[k] = v
 		}
 	}
-	if s.logTags != nil {
-		setLogTags(s.logTags.Get(), func(remappedKey string, tag *logtags.Tag) {
-			addTag(remappedKey, tag.ValueStr())
-		})
-	}
-	if len(s.mu.tags) > 0 {
-		for k, v := range s.mu.tags {
-			// We encode the tag values as strings.
-			addTag(k, fmt.Sprint(v))
+	if wantTags {
+		if s.logTags != nil {
+			setLogTags(s.logTags.Get(), func(remappedKey string, tag *logtags.Tag) {
+				addTag(remappedKey, tag.ValueStr())
+			})
+		}
+		if len(s.mu.tags) > 0 {
+			for k, v := range s.mu.tags {
+				// We encode the tag values as strings.
+				addTag(k, fmt.Sprint(v))
+			}
 		}
 	}
+
 	rs.Logs = make([]tracingpb.LogRecord, len(s.mu.recording.recordedLogs))
 	for i, r := range s.mu.recording.recordedLogs {
 		rs.Logs[i].Time = r.Timestamp

pkg/util/tracing/grpc_interceptor_test.go

@@ -55,7 +55,9 @@ func TestGRPCInterceptors(t *testing.T) {
 		}
 
 		sp.RecordStructured(&types.Int32Value{Value: magicValue})
+		sp.SetVerbose(true) // want the tags
 		recs := sp.GetRecording()
+		sp.SetVerbose(false)
 		if len(recs) != 1 {
 			return nil, errors.Newf("expected exactly one recorded span, not %+v", recs)
 		}
@@ -193,7 +195,9 @@ func TestGRPCInterceptors(t *testing.T) {
 			require.NoError(t, sp.ImportRemoteSpans([]tracingpb.RecordedSpan{rec}))
 			sp.Finish()
 			var n int
+			sp.SetVerbose(true) // to get the tags
 			finalRecs := sp.GetRecording()
+			sp.SetVerbose(false)
 			for _, rec := range finalRecs {
 				n += len(rec.InternalStructured)
 				// Remove all of the _unfinished tags. These crop up because
@@ -204,6 +208,7 @@ func TestGRPCInterceptors(t *testing.T) {
 				// Note that we check that we're not leaking spans at the end of
 				// the test.
 				delete(rec.Tags, "_unfinished")
+				delete(rec.Tags, "_verbose")
 			}
 			require.Equal(t, 1, n)
 

pkg/util/tracing/span.go

@@ -90,6 +90,10 @@ func (sp *Span) Finish() {
 // 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.
+//
+// As a performance optimization, GetRecording does not return tags when the
+// underlying Span is not verbose. Returning tags requires expensive
+// stringification.
 func (sp *Span) GetRecording() Recording {
 	// It's always valid to get the recording, even for a finished span.
 	return sp.i.GetRecording()
@@ -291,7 +295,10 @@ func (s *spanInner) ResetRecording() {
 }
 
 func (s *spanInner) GetRecording() Recording {
-	return s.crdb.getRecording(s.tracer.TracingVerbosityIndependentSemanticsIsActive())
+	// If the span is not verbose, optimize by avoiding the tags.
+	// This span is likely only used to carry payloads around.
+	wantTags := s.crdb.recordingType() == RecordingVerbose
+	return s.crdb.getRecording(s.tracer.TracingVerbosityIndependentSemanticsIsActive(), wantTags)
 }
 
 func (s *spanInner) ImportRemoteSpans(remoteSpans []tracingpb.RecordedSpan) error {

pkg/util/tracing/span_test.go

@@ -19,7 +19,9 @@ import (
 	"time"
 
 	"github.com/cockroachdb/errors"
+	"github.com/cockroachdb/logtags"
 	"github.com/gogo/protobuf/types"
+	"github.com/opentracing/opentracing-go"
 	"github.com/stretchr/testify/require"
 	"golang.org/x/net/trace"
 	"google.golang.org/grpc/metadata"
@@ -206,10 +208,9 @@ func TestSpanRecordStructured(t *testing.T) {
 	require.IsType(t, (*types.Int32Value)(nil), d1.Message)
 	require.NoError(t, TestingCheckRecordedSpans(rec, `
 		span: root
-			tags: _unfinished=1
 		`))
 	require.NoError(t, TestingCheckRecording(rec, `
-		=== operation:root _unfinished:1
+		=== operation:root
 	`))
 }
 
@@ -331,3 +332,34 @@ func TestSpan_UseAfterFinish(t *testing.T) {
 		})
 	}
 }
+
+type countingStringer int32
+
+func (i *countingStringer) String() string {
+	*i++ // not for concurrent use
+	return fmt.Sprint(*i)
+}
+
+func TestSpan_GetRecordingTags(t *testing.T) {
+	// Verify that tags are omitted from GetRecording if the span is
+	// not verbose when the recording is pulled. See GetRecording for
+	// details.
+	tr := NewTracer()
+	var counter countingStringer
+	logTags := logtags.SingleTagBuffer("tagfoo", "tagbar")
+	sp := tr.StartSpan("root",
+		WithForceRealSpan(),
+		WithTags(opentracing.Tag{
+			Key:   "foo1",
+			Value: &counter,
+		}),
+		WithLogTags(logTags),
+	)
+	defer sp.Finish()
+
+	require.False(t, sp.IsVerbose())
+	sp.SetTag("foo2", &counter)
+	rec := sp.GetRecording()
+	require.Empty(t, rec[0].Tags)
+	require.Zero(t, counter)
+}

pkg/util/tracing/tracer_test.go

@@ -67,7 +67,6 @@ func TestTracerRecording(t *testing.T) {
 	// Initial recording of this fresh (real) span.
 	if err := TestingCheckRecordedSpans(s1.GetRecording(), `
 		span: a
-			tags: _unfinished=1
 	`); err != nil {
 		t.Fatal(err)
 	}
@@ -145,7 +144,6 @@ func TestTracerRecording(t *testing.T) {
 	s1.Recordf("x=%d", 100)
 	if err := TestingCheckRecordedSpans(s1.GetRecording(), `
 		span: a
-			tags: _unfinished=1
 	`); err != nil {
 		t.Fatal(err)
 	}