Skip to content

Commit

Permalink
tracing: propagate non-recording spans across rpc boundaries
Browse files Browse the repository at this point in the history
We were previously propagating RPCs across boundaries only when they
were verbose. We now propagate any span (except the noop span)
regardless of current verbosity.
This ensures that SQL (which always creates real, non-verbose spans by
default) can trace the entirety of its operations.

This enables the background collection of contention metadata in 21.1
and more generally, the idea of always-on tracing. Note that we had
previously considered always-on tracing to mean avoiding the noop span
altogether; due to memory retention issues[1][2] encountered we are
taking a step back from that idea for the 21.1 release.

[1]: cockroachdb#59370
[2]: cockroachdb#59431

Release note: None

iasd
Release note: None
  • Loading branch information
tbg committed Feb 8, 2021
1 parent 5b33e6d commit f9cbe57
Show file tree
Hide file tree
Showing 6 changed files with 65 additions and 36 deletions.
11 changes: 2 additions & 9 deletions pkg/util/tracing/crdbspan.go
Original file line number Diff line number Diff line change
Expand Up @@ -136,16 +136,9 @@ func (s *crdbSpan) disableRecording() {

func (s *crdbSpan) getRecording(m mode) Recording {
if s == nil {
return nil
}
if m == modeLegacy && s.recordingType() == RecordingOff {
// In legacy tracing (pre always-on), we avoid allocations when the
// Span is not actively recording.
//
// TODO(tbg): we could consider doing the same when background tracing
// is on but the current span contains "nothing of interest".
return nil
return nil // noop span
}

s.mu.Lock()
// The capacity here is approximate since we don't know how many grandchildren
// there are.
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/tracing/grpc_interceptor.go
Original file line number Diff line number Diff line change
Expand Up @@ -73,7 +73,7 @@ func spanInclusionFuncForServer(t *Tracer, spanMeta *SpanMeta) bool {
// configured to always trace, return true. The second part is particularly
// useful for calls coming through the HTTP->RPC gateway (i.e. the AdminUI),
// where client is never tracing.
return !spanMeta.isNilOrNoop() || t.AlwaysTrace()
return spanMeta != nil || t.AlwaysTrace()
}

// SetSpanTags sets one or more tags on the given span according to the
Expand Down
7 changes: 0 additions & 7 deletions pkg/util/tracing/span.go
Original file line number Diff line number Diff line change
Expand Up @@ -174,13 +174,6 @@ func (s *Span) IsBlackHole() bool {
return s.crdb.recordingType() == RecordingOff && s.netTr == nil && s.ot == (otSpan{})
}

// isNilOrNoop returns true if the Span context is either nil
// or corresponds to a "no-op" Span. If this is true, any Span
// derived from this context will be a "black hole Span".
func (sm *SpanMeta) isNilOrNoop() bool {
return sm == nil || (sm.recordingType == RecordingOff && sm.shadowTracerType == "")
}

// SpanStats are stats that can be added to a Span.
type SpanStats interface {
protoutil.Message
Expand Down
1 change: 0 additions & 1 deletion pkg/util/tracing/span_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -184,7 +184,6 @@ Span grandchild:

func TestSpan_LogStructured(t *testing.T) {
tr := NewTracer()
tr._mode = int32(modeBackground)
sp := tr.StartSpan("root", WithForceRealSpan())
defer sp.Finish()

Expand Down
16 changes: 7 additions & 9 deletions pkg/util/tracing/tracer.go
Original file line number Diff line number Diff line change
Expand Up @@ -289,14 +289,12 @@ func (t *Tracer) startSpanGeneric(
opts.LogTags = logtags.FromContext(ctx)
}

// Avoid creating a real span when possible. If tracing is globally
// enabled, we always need to create spans. If the incoming
// span is recording (which implies that there is a parent) then
// we also have to create a real child. Additionally, if the
// caller explicitly asked for a real span they need to get one.
// In all other cases, a noop span will do.
// Avoid creating a real span when possible. If tracing is globally enabled,
// we always need to create spans. If the incoming span has a parent, then we
// also create a real child. Additionally, if the caller explicitly asked for
// a real span they need to get one. In all other cases, a noop span will do.
if !t.AlwaysTrace() &&
opts.recordingType() == RecordingOff &&
opts.parentTraceID() == 0 &&
!opts.ForceRealSpan {
return maybeWrapCtx(ctx, nil /* octx */, t.noopSpan)
}
Expand Down Expand Up @@ -464,7 +462,7 @@ func (fn textMapWriterFn) Set(key, val string) {

// Inject is part of the opentracing.Tracer interface.
func (t *Tracer) Inject(sc *SpanMeta, format interface{}, carrier interface{}) error {
if sc.isNilOrNoop() {
if sc == nil {
// Fast path when tracing is disabled. Extract will accept an empty map as a
// noop context.
return nil
Expand Down Expand Up @@ -507,7 +505,7 @@ func (t *Tracer) Inject(sc *SpanMeta, format interface{}, carrier interface{}) e
return nil
}

var noopSpanContext = &SpanMeta{}
var noopSpanContext = (*SpanMeta)(nil)

// Extract is part of the opentracing.Tracer interface.
// It always returns a valid context, even in error cases (this is assumed by the
Expand Down
64 changes: 55 additions & 9 deletions pkg/util/tracing/tracer_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,9 @@ func TestTracerRecording(t *testing.T) {
}
noop1.Record("hello")

// Noop span returns empty recording.
require.Equal(t, Recording(nil), noop1.GetRecording())

noop2 := tr.StartSpan("noop2", WithParentAndManualCollection(noop1.Meta()))
if !noop2.isNoop() {
t.Error("expected noop child Span")
Expand All @@ -61,12 +64,20 @@ func TestTracerRecording(t *testing.T) {
t.Error("WithForceRealSpan Span should be black hole")
}

// Unless recording is actually started, child spans are still noop.
noop3 := tr.StartSpan("noop3", WithParentAndManualCollection(s1.Meta()))
if !noop3.isNoop() {
t.Error("expected noop child Span")
// Initial recording of this fresh (real) span.
if err := TestingCheckRecordedSpans(s1.GetRecording(), `
Span a:
tags: _unfinished=1
`); err != nil {
t.Fatal(err)
}
noop3.Finish()

// Real parent --> real child.
real3 := tr.StartSpan("noop3", WithParentAndManualCollection(s1.Meta()))
if real3.isNoop() {
t.Error("expected real child Span")
}
real3.Finish()

s1.Recordf("x=%d", 1)
s1.SetVerbose(true)
Expand Down Expand Up @@ -116,7 +127,7 @@ func TestTracerRecording(t *testing.T) {
t.Fatal(err)
}
s3.Finish()
if err := TestingCheckRecordedSpans(s1.GetRecording(), `
expS1v := `
Span a:
tags: _unfinished=1 _verbose=1
event: x=2
Expand All @@ -126,12 +137,26 @@ func TestTracerRecording(t *testing.T) {
Span c:
tags: _verbose=1 tag=val
event: x=4
`); err != nil {
`
if err := TestingCheckRecordedSpans(s1.GetRecording(), expS1v); err != nil {
t.Fatal(err)
}
// When we turn off verbosity and add more verbose logs, they get
// dropped, i.e. the recording is unchanged mod the _verbose flag.
expS1n := `
Span a:
tags: _unfinished=1
event: x=2
Span b:
tags: _verbose=1
event: x=3
Span c:
tags: _verbose=1 tag=val
event: x=4
`
s1.SetVerbose(false)
s1.Recordf("x=%d", 100)
if err := TestingCheckRecordedSpans(s1.GetRecording(), ``); err != nil {
if err := TestingCheckRecordedSpans(s1.GetRecording(), expS1n); err != nil {
t.Fatal(err)
}

Expand Down Expand Up @@ -223,7 +248,7 @@ func TestTracerInjectExtract(t *testing.T) {
if err != nil {
t.Fatal(err)
}
if !wireContext.isNilOrNoop() {
if wireContext != nil {
t.Errorf("expected noop context: %v", wireContext)
}
noop2 := tr2.StartSpan("remote op", WithParentAndManualCollection(wireContext))
Expand Down Expand Up @@ -292,6 +317,27 @@ func TestTracerInjectExtract(t *testing.T) {
}
}

func TestTracer_PropagateNonRecordingRealSpanAcrossRPCBoundaries(t *testing.T) {
// Verify that when a span is put on the wire on one end, and is checked
// against the span inclusion functions both on the client and server, a real
// span results in a real span.
tr1 := NewTracer()
sp1 := tr1.StartSpan("tr1.root", WithForceRealSpan())
defer sp1.Finish()
carrier := make(opentracing.HTTPHeadersCarrier)
require.True(t, spanInclusionFuncForClient(sp1))
require.NoError(t, tr1.Inject(sp1.Meta(), opentracing.HTTPHeaders, carrier))
require.Len(t, carrier, 2) // trace id and span id

tr2 := NewTracer()
meta, err := tr2.Extract(opentracing.HTTPHeaders, carrier)
require.NoError(t, err)
require.True(t, spanInclusionFuncForServer(tr2, meta))
sp2 := tr2.StartSpan("tr2.child", WithParentAndManualCollection(meta))
defer sp2.Finish()
require.NotZero(t, sp2.crdb.spanID)
}

func TestLightstepContext(t *testing.T) {
tr := NewTracer()
lsTr := lightstep.NewTracer(lightstep.Options{
Expand Down

0 comments on commit f9cbe57

Please sign in to comment.