Skip to content

Commit

Permalink
tracing: add startSpanFast for optimized path when disabled
Browse files Browse the repository at this point in the history
This change attempts to reduce the impact of `StartSpanCtx` when
called with tracing disabled.

A new fast path is introduced via the `spanSpanFast` method which
avoids the more complex logic within `startSpanGeneric`.

Additionally, the regexp-based verbose tracing is modified to use an
atomic pointer instead of a mutex, and the `SpanOption` iterator is
modified to avoid extra copies.

Below are benchmark results which show the most impact on `opts=none` cpu.
```
❯ benchdiff  ./pkg/util/tracing --old ':/consolidate regexp bench' -b -r 'BenchmarkTracer_StartSpanCtx' -d 100000x -c 10
test binaries already exist for a2746cd: tracing: consolidate regexp bench into BenchmarkTr
test binaries already exist for 41fdcda: tracing: add startSpanFast for optimized path when

  pkg=1/1 iter=10/10 cockroachdb/cockroach/pkg/util/tracing \

name                                                                            old time/op    new time/op    delta
Tracer_StartSpanCtx/opts=none/parallel=true-10                                     164ns ±10%      16ns ±64%  -90.12%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=none/parallel=false-10                                   56.1ns ± 5%    47.7ns ± 5%  -14.96%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real/parallel=true-10                                     584ns ± 3%     546ns ±20%   -6.51%  (p=0.002 n=8+9)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=true-10                          636ns ± 5%     615ns ± 4%   -3.37%  (p=0.014 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=false-10                         318ns ± 3%     308ns ± 3%   -2.92%  (p=0.001 n=10+9)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=false-10       473ns ± 3%     460ns ± 1%   -2.79%  (p=0.000 n=10+8)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=true-10      669ns ± 4%     651ns ± 2%   -2.71%  (p=0.014 n=9+9)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=false-10     353ns ± 2%     348ns ± 4%   -1.32%  (p=0.019 n=9+9)
Tracer_StartSpanCtx/opts=real/parallel=false-10                                    285ns ± 3%     284ns ± 1%     ~     (p=0.923 n=10+9)
Tracer_StartSpanCtx/opts=real,logtag/parallel=false-10                             303ns ± 4%     303ns ± 3%     ~     (p=0.811 n=10+10)
Tracer_StartSpanCtx/opts=real,logtag/parallel=true-10                              590ns ± 2%     585ns ± 3%     ~     (p=0.190 n=9+9)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=false-10                       338ns ± 3%     333ns ± 3%     ~     (p=0.052 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=true-10                        651ns ± 4%     639ns ± 4%     ~     (p=0.052 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=true-10        910ns ±18%     880ns ±24%     ~     (p=0.436 n=10+10)
Tracer_StartSpanCtx/opts=real,regexp/parallel=true-10                              741ns ± 3%     808ns ± 2%   +9.10%  (p=0.000 n=9+10)
Tracer_StartSpanCtx/opts=real,regexp/parallel=false-10                             500ns ± 1%     722ns ± 1%  +44.49%  (p=0.000 n=8+8)

name                                                                            old alloc/op   new alloc/op   delta
Tracer_StartSpanCtx/opts=none/parallel=false-10                                    48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=none/parallel=true-10                                     48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real/parallel=false-10                                    48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real/parallel=true-10                                     48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag/parallel=false-10                             48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag/parallel=true-10                              48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=false-10                         48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=true-10                          48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=false-10                       48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=true-10                        48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=false-10       96.0B ± 0%     96.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=true-10        96.0B ± 0%     96.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=false-10     48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=true-10      48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,regexp/parallel=false-10                             48.0B ± 0%     48.0B ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,regexp/parallel=true-10                              51.0B ± 0%     51.0B ± 0%     ~     (all equal)

name                                                                            old allocs/op  new allocs/op  delta
Tracer_StartSpanCtx/opts=none/parallel=false-10                                     1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=none/parallel=true-10                                      1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real/parallel=false-10                                     1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real/parallel=true-10                                      1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag/parallel=false-10                              1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag/parallel=true-10                               1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=false-10                          1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent/parallel=true-10                           1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=false-10                        1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent/parallel=true-10                         1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=false-10        2.00 ± 0%      2.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener/parallel=true-10         2.00 ± 0%      2.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=false-10      1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener/parallel=true-10       1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,regexp/parallel=false-10                              1.00 ± 0%      1.00 ± 0%     ~     (all equal)
Tracer_StartSpanCtx/opts=real,regexp/parallel=true-10                               1.00 ± 0%      1.00 ± 0%     ~     (all equal)
```

Part of: cockroachdb#133307
Epic: CRDB-42854

Release note: None
  • Loading branch information
dhartunian committed Dec 9, 2024
1 parent e20a781 commit ac41722
Show file tree
Hide file tree
Showing 2 changed files with 50 additions and 19 deletions.
6 changes: 6 additions & 0 deletions pkg/util/tracing/span_options.go
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,12 @@ func (opts *spanOptions) parentSpanID() tracingpb.SpanID {
return 0
}

// recordingType computes the resulting recording type of the span
// based on various settings. Please note that some of this logic is
// partially duplicates in `Tracer.startSpanFast` which is used for
// spans without a parent and avoids calling this method for
// performance reasons. If you modify this method, make sure to modify
// `startSpanFast` as well.
func (opts *spanOptions) recordingType() tracingpb.RecordingType {
if opts.recordingTypeExplicit {
return opts.recordingTypeOpt
Expand Down
63 changes: 44 additions & 19 deletions pkg/util/tracing/tracer.go
Original file line number Diff line number Diff line change
Expand Up @@ -313,12 +313,7 @@ type Tracer struct {
// explicitly requested.
_activeSpansRegistryEnabled int32 // accessed atomically

forceVerboseMu struct {
syncutil.RWMutex
// opNameRegexp is matched against during span initialization. If the span
// operation name matches, then the span is forced to a VERBOSE recording mode.
opNameRegexp *regexp.Regexp
}
opNameRegexp atomic.Pointer[regexp.Regexp]

// activeSpans is a map that references all non-Finish'ed local root spans,
// i.e. those for which no WithParent(<non-nil>) option was supplied.
Expand Down Expand Up @@ -774,17 +769,15 @@ func WithUseAfterFinishOpt(panicOnUseAfterFinish, debugUseAfterFinish bool) Trac
}

func (t *Tracer) setVerboseOpNameRegexp(s string) error {
t.forceVerboseMu.Lock()
defer t.forceVerboseMu.Unlock()
if s == "" {
t.forceVerboseMu.opNameRegexp = nil
t.opNameRegexp.Store(nil)
return nil
}
compiled, err := regexp.Compile(s)
if err != nil {
return err
}
t.forceVerboseMu.opNameRegexp = compiled
t.opNameRegexp.Store(compiled)
return nil
}

Expand Down Expand Up @@ -1078,14 +1071,14 @@ func (t *Tracer) StartSpanCtx(
// NB: apply takes and returns a value to avoid forcing
// `opts` on the heap here.
var opts spanOptions
for _, o := range os {
if o == nil {
for i := range os {
if os[i] == nil {
continue
}
opts = o.apply(opts)
opts = os[i].apply(opts)
}

return t.startSpanGeneric(ctx, operationName, opts)
return t.startSpanFast(ctx, operationName, opts)
}

// AlwaysTrace returns true if operations should be traced regardless of the
Expand All @@ -1099,12 +1092,44 @@ func (t *Tracer) AlwaysTrace() bool {
}

func (t *Tracer) forceOpNameVerbose(opName string) bool {
t.forceVerboseMu.RLock()
defer t.forceVerboseMu.RUnlock()
if t.forceVerboseMu.opNameRegexp == nil {
return false
if r := t.opNameRegexp.Load(); r != nil {
return r.MatchString(opName)
}
return false
}

func (t *Tracer) startSpanFast(
ctx context.Context, opName string, opts spanOptions,
) (context.Context, *Span) {
if opts.RefType != childOfRef && opts.RefType != followsFromRef {
panic(errors.AssertionFailedf("unexpected RefType %v", opts.RefType))
}

// This is a fast path for the common case where there's no parent
// span. This contains duplicated logic from
// `(*spanOptions).recordingType()`. Specifically, we are aiming to
// avoid creating local copies of `opts.Parent` and
// `opts.RemoteParent` hence conditional logic is being inlined and
// checked locally. This logic should only change if
// `recordingType()` is being modified.
if opts.Parent.Span == nil && opts.RemoteParent.Empty() {
var recordingType tracingpb.RecordingType

if opts.recordingTypeExplicit {
recordingType = opts.recordingTypeOpt
}

if recordingType < opts.minRecordingTypeOpt {
recordingType = opts.minRecordingTypeOpt
}

shouldBeNoopSpan := !(t.AlwaysTrace() || opts.ForceRealSpan || recordingType != tracingpb.RecordingOff)
forceVerbose := t.forceOpNameVerbose(opName)
if shouldBeNoopSpan && !forceVerbose && !opts.Sterile {
return maybeWrapCtx(ctx, t.noopSpan)
}
}
return t.forceVerboseMu.opNameRegexp.MatchString(opName)
return t.startSpanGeneric(ctx, opName, opts)
}

// startSpanGeneric is the implementation of StartSpanCtx and StartSpan. In
Expand Down

0 comments on commit ac41722

Please sign in to comment.