From c8f9f610c14f131b1c86bdc24e7d45bfafe2995d Mon Sep 17 00:00:00 2001 From: Tobias Grieger Date: Thu, 25 Feb 2021 11:08:59 +0100 Subject: [PATCH 1/2] 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 | 46 +++++++++++++---------- pkg/util/tracing/grpc_interceptor_test.go | 5 +++ pkg/util/tracing/span.go | 9 ++++- pkg/util/tracing/span_test.go | 36 +++++++++++++++++- pkg/util/tracing/tracer_test.go | 2 - 5 files changed, 73 insertions(+), 25 deletions(-) diff --git a/pkg/util/tracing/crdbspan.go b/pkg/util/tracing/crdbspan.go index ea61f462fb1a..187620bf933b 100644 --- a/pkg/util/tracing/crdbspan.go +++ b/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 diff --git a/pkg/util/tracing/grpc_interceptor_test.go b/pkg/util/tracing/grpc_interceptor_test.go index 7d8dbb9a373c..8991775ebe45 100644 --- a/pkg/util/tracing/grpc_interceptor_test.go +++ b/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) diff --git a/pkg/util/tracing/span.go b/pkg/util/tracing/span.go index 2206e816df17..e96044209086 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() @@ -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 { diff --git a/pkg/util/tracing/span_test.go b/pkg/util/tracing/span_test.go index 7a8446d7edec..fae2aaa2e192 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" @@ -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) +} diff --git a/pkg/util/tracing/tracer_test.go b/pkg/util/tracing/tracer_test.go index 48a5da8d38f4..7fbd2d4fc6c7 100644 --- a/pkg/util/tracing/tracer_test.go +++ b/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) } From bec47d32fd2fbb99cda1764bd66194547389c2e1 Mon Sep 17 00:00:00 2001 From: Tobias Grieger Date: Thu, 25 Feb 2021 11:30:37 +0100 Subject: [PATCH 2/2] cluster: perf optimize tracer's version feature gate `version.IsActive` unmarshals a protobuf (and this isn't trivial to fix), so let the tracer cache a positive result. This means that in the common case, IsActive is not on the hot path any more. Release justification: low-risk performance improvement Release note: None --- pkg/settings/cluster/cluster_settings.go | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/pkg/settings/cluster/cluster_settings.go b/pkg/settings/cluster/cluster_settings.go index 7d6c461ba62a..aa0cd7e7a238 100644 --- a/pkg/settings/cluster/cluster_settings.go +++ b/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)