From 95fc831856bf851bbc1c821425e2a54c7c14a2f5 Mon Sep 17 00:00:00 2001
From: Tobias Grieger <tobias.b.grieger@gmail.com>
Date: Thu, 25 Feb 2021 11:08:59 +0100
Subject: [PATCH] tracing: elide tags from recording if not verbose

This avoids some of the obviously problematic expensive stringifications
observed in https://github.com/cockroachdb/cockroach/issues/59379.

Release justification: low-risk performance optimization that unblocks sql stats.
Release note: None
---
 pkg/util/tracing/crdbspan.go  | 39 +++++++++++++++++++++--------------
 pkg/util/tracing/span.go      |  4 ++++
 pkg/util/tracing/span_test.go | 33 +++++++++++++++++++++++++++++
 3 files changed, 60 insertions(+), 16 deletions(-)

diff --git a/pkg/util/tracing/crdbspan.go b/pkg/util/tracing/crdbspan.go
index ea61f462fb1a..ab7569326602 100644
--- a/pkg/util/tracing/crdbspan.go
+++ b/pkg/util/tracing/crdbspan.go
@@ -278,6 +278,8 @@ func (s *crdbSpan) getRecordingLocked() tracingpb.RecordedSpan {
 		rs.Finished = true
 	}
 
+	wantTags := s.recordingType() == RecordingVerbose
+
 	addTag := func(k, v string) {
 		if rs.Tags == nil {
 			rs.Tags = make(map[string]string)
@@ -285,13 +287,15 @@ 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 {
+		// 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 s.mu.stats != nil {
@@ -322,17 +326,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
diff --git a/pkg/util/tracing/span.go b/pkg/util/tracing/span.go
index 2206e816df17..23368df9388e 100644
--- a/pkg/util/tracing/span.go
+++ b/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()
diff --git a/pkg/util/tracing/span_test.go b/pkg/util/tracing/span_test.go
index 7a8446d7edec..52794ac887ee 100644
--- a/pkg/util/tracing/span_test.go
+++ b/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"
@@ -331,3 +333,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)
+}