Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tracing: introduce a minimal tracing mode and enable in tests #73407

Merged
merged 3 commits into from
Dec 9, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 7 additions & 0 deletions pkg/base/test_server_args.go
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,11 @@ type TestServerArgs struct {
// IF set, the demo login endpoint will be enabled.
EnableDemoLoginEndpoint bool

// Tracer, if set, will be used by the Server for creating Spans.
Tracer *tracing.Tracer
// TracingDefault kicks in if Tracer is not set. It is passed to the Tracer
// that will be created for the server.
TracingDefault tracing.TracingMode
// If set, a TraceDir is initialized at the provided path.
TraceDir string

Expand Down Expand Up @@ -297,4 +301,7 @@ type TestTenantArgs struct {
// StartingHTTPPort, if it is non-zero, is added to the tenant ID in order to
// determine the tenant's HTTP port.
StartingHTTPPort int

// TracingDefault controls whether the tracing will be on or off by default.
TracingDefault tracing.TracingMode
}
17 changes: 12 additions & 5 deletions pkg/bench/bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -507,11 +507,18 @@ func BenchmarkTracing(b *testing.B) {
name.WriteString(fmt.Sprintf("%d%%", percent))
}
b.Run(name.String(), func(b *testing.B) {
tr := tracing.NewTracerWithOpt(ctx,
tracing.WithTestingKnobs(tracing.TracerTestingKnobs{
ForceRealSpans: test.alwaysTrace,
UseNetTrace: test.netTrace,
}))
var opts []tracing.TracerOption
opts = append(opts, tracing.WithTestingKnobs(tracing.TracerTestingKnobs{
UseNetTrace: test.netTrace,
}))
var o tracing.TracingMode
if !test.alwaysTrace {
o = tracing.TracingModeOnDemand
} else {
o = tracing.TracingModeActiveSpansRegistry
}
opts = append(opts, tracing.WithTracingMode(o))
tr := tracing.NewTracerWithOpt(ctx, opts...)
sqlRunner, stop := cluster.create(tr)
defer stop.Stop(ctx)

Expand Down
38 changes: 0 additions & 38 deletions pkg/jobs/jobs_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -1010,44 +1010,6 @@ func TestRegistryLifecycle(t *testing.T) {
rts.mu.e.Success = true
rts.check(t, jobs.StatusSucceeded)
})
t.Run("trace ID only set if requested", func(t *testing.T) {
// The trace ID can be set on the job if the job should be traced.
// Not all jobs should be traced. If the job is not being traced,
// ensure that we do not do an extra write to set it.

rts := registryTestSuite{}
rts.setUp(t)
defer rts.tearDown()

// Inject an error in the update to record the trace ID.
var updateCalls int
rts.beforeUpdate = func(orig, updated jobs.JobMetadata) error {
updateCalls++
return nil
}

runJob := func(t *testing.T) int {
t.Helper()
j, err := jobs.TestingCreateAndStartJob(context.Background(), rts.registry, rts.s.DB(), rts.mockJob)
require.NoError(t, err)
rts.job = j

// Make sure the job succeeds.
rts.resumeCheckCh <- struct{}{}
rts.resumeCh <- nil
rts.mu.e.ResumeStart = true
rts.mu.e.ResumeExit++
rts.mu.e.Success = true
rts.check(t, jobs.StatusSucceeded)
return updateCalls
}

updatedWithoutTracing := runJob(t)
updateCalls = 0
rts.traceRealSpan = true
updatedWithTracing := runJob(t)
require.Equal(t, updatedWithoutTracing, updatedWithTracing-1)
})

t.Run("dump traces on pause-unpause-success", func(t *testing.T) {
completeCh := make(chan struct{})
Expand Down
6 changes: 3 additions & 3 deletions pkg/server/testserver.go
Original file line number Diff line number Diff line change
Expand Up @@ -140,7 +140,7 @@ func makeTestConfigFromParams(params base.TestServerArgs) Config {
st.ExternalIODir = params.ExternalIODir
tr := params.Tracer
if params.Tracer == nil {
tr = tracing.NewTracerWithOpt(context.TODO(), tracing.WithClusterSettings(&st.SV))
tr = tracing.NewTracerWithOpt(context.TODO(), tracing.WithClusterSettings(&st.SV), tracing.WithTracingMode(params.TracingDefault))
}
cfg := makeTestConfig(st, tr)
cfg.TestingKnobs = params.Knobs
Expand Down Expand Up @@ -644,12 +644,12 @@ func (ts *TestServer) StartTenant(
if stopper == nil {
// We don't share the stopper with the server because we want their Tracers
// to be different, to simulate them being different processes.
tr := tracing.NewTracerWithOpt(ctx, tracing.WithClusterSettings(&st.SV))
tr := tracing.NewTracerWithOpt(ctx, tracing.WithClusterSettings(&st.SV), tracing.WithTracingMode(params.TracingDefault))
stopper = stop.NewStopper(stop.WithTracer(tr))
// The server's stopper stops the tenant, for convenience.
ts.Stopper().AddCloser(stop.CloserFn(func() { stopper.Stop(context.Background()) }))
} else if stopper.Tracer() == nil {
tr := tracing.NewTracerWithOpt(ctx, tracing.WithClusterSettings(&st.SV))
tr := tracing.NewTracerWithOpt(ctx, tracing.WithClusterSettings(&st.SV), tracing.WithTracingMode(params.TracingDefault))
stopper.SetTracer(tr)
}

Expand Down
1 change: 1 addition & 0 deletions pkg/sql/logictest/BUILD.bazel
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,7 @@ go_library(
"//pkg/util/randutil",
"//pkg/util/syncutil",
"//pkg/util/timeutil",
"//pkg/util/tracing",
"@com_github_cockroachdb_errors//:errors",
"@com_github_cockroachdb_errors//oserror",
"@com_github_lib_pq//:pq",
Expand Down
17 changes: 17 additions & 0 deletions pkg/sql/logictest/logic.go
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,7 @@ import (
"github.com/cockroachdb/cockroach/pkg/util/randutil"
"github.com/cockroachdb/cockroach/pkg/util/syncutil"
"github.com/cockroachdb/cockroach/pkg/util/timeutil"
"github.com/cockroachdb/cockroach/pkg/util/tracing"
"github.com/cockroachdb/errors"
"github.com/cockroachdb/errors/oserror"
"github.com/lib/pq"
Expand Down Expand Up @@ -165,6 +166,9 @@ import (
// The options are:
// - enable-span-config: If specified, the span configs infrastructure will be
// enabled. This is equivalent to setting COCKROACH_EXPERIMENTAL_SPAN_CONFIGS.
// - tracing-off: If specified, tracing defaults to being turned off. This is
// used to override the environment, which may ask for tracing to be on by
// default.
//
//
// ###########################################
Expand Down Expand Up @@ -1540,6 +1544,7 @@ func (t *logicTest) newCluster(serverArgs TestServerArgs, opts []clusterOpt) {
TempStorageConfig: &params.ServerArgs.TempStorageConfig,
Locality: paramsPerNode[i].Locality,
Existing: i > 0,
TracingDefault: params.ServerArgs.TracingDefault,
}

// Prevent a logging assertion that the server ID is initialized multiple times.
Expand Down Expand Up @@ -1877,6 +1882,16 @@ func (c clusterOptSpanConfigs) apply(args *base.TestServerArgs) {
args.EnableSpanConfigs = true
}

// clusterOptTracingOff corresponds to the tracing-off directive.
type clusterOptTracingOff struct{}

var _ clusterOpt = clusterOptTracingOff{}

// apply implements the clusterOpt interface.
func (c clusterOptTracingOff) apply(args *base.TestServerArgs) {
args.TracingDefault = tracing.TracingModeOnDemand
}

// readClusterOptions looks around the beginning of the file for a line looking like:
// # cluster-opt: opt1 opt2 ...
// and parses that line into a set of clusterOpts that need to be applied to the
Expand Down Expand Up @@ -1915,6 +1930,8 @@ func readClusterOptions(t *testing.T, path string) []clusterOpt {
switch opt {
case "enable-span-configs":
res = append(res, clusterOptSpanConfigs{})
case "tracing-off":
res = append(res, clusterOptTracingOff{})
default:
t.Fatalf("unrecognized cluster option: %s", opt)
}
Expand Down
5 changes: 5 additions & 0 deletions pkg/sql/logictest/testdata/logic_test/inflight_trace_spans
Original file line number Diff line number Diff line change
@@ -1,6 +1,11 @@
# Verify that the crdb_internal.node_inflight_trace_spans vtable populates
# correctly.

# This test wants tracing to be generally off across the cluster, otherwise it
# picks up more spans than it wants.
# TODO(andrei): Figure out a replacement for this test that is more robust.
# cluster-opt: tracing-off

statement ok
GRANT ADMIN TO testuser

Expand Down
4 changes: 3 additions & 1 deletion pkg/testutils/lint/lint_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -1654,10 +1654,12 @@ func TestLint(t *testing.T) {
stream.GrepNot("pkg/sql/types/types.go.* var Uuid should be UUID"),
stream.GrepNot("pkg/sql/oidext/oidext.go.*don't use underscores in Go names; const T_"),
stream.GrepNot("server/api_v2.go.*package comment should be of the form"),
stream.GrepNot("type name will be used as row.RowLimit by other packages, and that stutters; consider calling this Limit"),
stream.GrepNot("pkg/util/timeutil/time_zone_util.go.*error strings should not be capitalized or end with punctuation or a newline"),
stream.GrepNot("pkg/sql/job_exec_context_test_util.go.*exported method ExtendedEvalContext returns unexported type"),
stream.GrepNot("pkg/sql/job_exec_context_test_util.go.*exported method SessionDataMutatorIterator returns unexported type"),

stream.GrepNot("type name will be used as row.RowLimit by other packages, and that stutters; consider calling this Limit"),
stream.GrepNot("type name will be used as tracing.TracingMode by other packages, and that stutters; consider calling this Mode"),
), func(s string) {
t.Errorf("\n%s", s)
}); err != nil {
Expand Down
7 changes: 1 addition & 6 deletions pkg/util/stop/stopper_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -687,12 +687,7 @@ func (cf closerFunc) Close() { cf() }
// the ChildSpan option.
func TestStopperRunAsyncTaskTracing(t *testing.T) {
defer leaktest.AfterTest(t)()
tr := tracing.NewTracerWithOpt(context.Background(), tracing.WithTestingKnobs(
tracing.TracerTestingKnobs{
// We want the tracer to generate real spans so that we can test that the
// RootSpan option produces a root span.
ForceRealSpans: true,
}))
tr := tracing.NewTracerWithOpt(context.Background(), tracing.WithTracingMode(tracing.TracingModeActiveSpansRegistry))
s := stop.NewStopper(stop.WithTracer(tr))

ctx, getRecAndFinish := tracing.ContextWithRecordingSpan(context.Background(), tr, "parent")
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/tracing/BUILD.bazel
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ go_library(
visibility = ["//visibility:public"],
deps = [
"//pkg/settings",
"//pkg/util/buildutil",
"//pkg/util/envutil",
"//pkg/util/iterutil",
"//pkg/util/netutil/addr",
Expand Down Expand Up @@ -66,7 +67,6 @@ go_test(
],
embed = [":tracing"],
deps = [
"//pkg/settings",
"//pkg/testutils",
"//pkg/testutils/grpcutils",
"//pkg/util",
Expand Down
58 changes: 23 additions & 35 deletions pkg/util/tracing/bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,6 @@ import (
"fmt"
"testing"

"github.com/cockroachdb/cockroach/pkg/settings"
"github.com/cockroachdb/logtags"
"github.com/gogo/protobuf/types"
)
Expand All @@ -28,37 +27,31 @@ import (
func BenchmarkTracer_StartSpanCtx(b *testing.B) {
ctx := context.Background()

tr := NewTracer()
sv := settings.Values{}
tr.Configure(ctx, &sv)

staticLogTags := logtags.Buffer{}
staticLogTags.Add("foo", "bar")

b.ResetTimer()

parSp := tr.StartSpan("one-off", WithForceRealSpan())
defer parSp.Finish()

for _, tc := range []struct {
name string
opts []SpanOption
name string
defaultMode TracingMode
parent bool
opts []SpanOption
}{
{"none", nil},
{"real", []SpanOption{
WithForceRealSpan(),
}},
{"real,logtag", []SpanOption{
WithForceRealSpan(), WithLogTags(&staticLogTags),
}},
{"real,autoparent", []SpanOption{
WithForceRealSpan(), WithParent(parSp),
}},
{"real,manualparent", []SpanOption{
WithForceRealSpan(), WithParent(parSp), WithDetachedRecording(),
}},
{"none", TracingModeOnDemand, false, nil},
{"real", TracingModeActiveSpansRegistry, false, nil},
{"real,logtag", TracingModeActiveSpansRegistry, false, []SpanOption{WithLogTags(&staticLogTags)}},
{"real,autoparent", TracingModeActiveSpansRegistry, true, nil},
{"real,manualparent", TracingModeActiveSpansRegistry, true, []SpanOption{WithDetachedRecording()}},
} {
b.Run(fmt.Sprintf("opts=%s", tc.name), func(b *testing.B) {
tr := NewTracerWithOpt(ctx, WithTracingMode(TracingModeActiveSpansRegistry))
b.ResetTimer()

if tc.parent {
parSp := tr.StartSpan("one-off")
defer parSp.Finish()
tc.opts = append(tc.opts, WithParent(parSp))
}

b.ReportAllocs()
for i := 0; i < b.N; i++ {
newCtx, sp := tr.StartSpanCtx(ctx, "benching", tc.opts...)
Expand All @@ -73,11 +66,9 @@ func BenchmarkTracer_StartSpanCtx(b *testing.B) {
// BenchmarkSpan_GetRecording microbenchmarks GetRecording.
func BenchmarkSpan_GetRecording(b *testing.B) {
ctx := context.Background()
var sv settings.Values
tr := NewTracer()
tr.Configure(ctx, &sv)
tr := NewTracerWithOpt(ctx, WithTracingMode(TracingModeActiveSpansRegistry))

sp := tr.StartSpan("foo", WithForceRealSpan())
sp := tr.StartSpan("foo")

run := func(b *testing.B, sp *Span) {
b.ReportAllocs()
Expand All @@ -91,7 +82,7 @@ func BenchmarkSpan_GetRecording(b *testing.B) {
run(b, sp)
})

child := tr.StartSpan("bar", WithParent(sp), WithForceRealSpan())
child := tr.StartSpan("bar", WithParent(sp))
b.Run("child-only", func(b *testing.B) {
run(b, child)
})
Expand All @@ -102,8 +93,7 @@ func BenchmarkSpan_GetRecording(b *testing.B) {
}

func BenchmarkRecordingWithStructuredEvent(b *testing.B) {
tr := NewTracerWithOpt(context.Background(),
WithTestingKnobs(TracerTestingKnobs{ForceRealSpans: true}))
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeActiveSpansRegistry))

ev := &types.Int32Value{Value: 5}
b.ReportAllocs()
Expand All @@ -119,9 +109,7 @@ func BenchmarkRecordingWithStructuredEvent(b *testing.B) {

// BenchmarkSpanCreation creates traces with a couple of spans in them.
func BenchmarkSpanCreation(b *testing.B) {
tr := NewTracerWithOpt(context.Background(), WithTestingKnobs(TracerTestingKnobs{
ForceRealSpans: true,
}))
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeActiveSpansRegistry))
const numChildren = 5
childNames := make([]string, numChildren)
for i := 0; i < numChildren; i++ {
Expand Down
4 changes: 2 additions & 2 deletions pkg/util/tracing/span_options.go
Original file line number Diff line number Diff line change
Expand Up @@ -297,8 +297,8 @@ type forceRealSpanOption struct{}

var forceRealSpanSingleton = SpanOption(forceRealSpanOption{})

// WithForceRealSpan forces StartSpan to create of a real Span instead of
// a low-overhead non-recordable noop span.
// WithForceRealSpan forces StartSpan to create of a real Span regardless of the
// Tracer's tracing mode (instead of a low-overhead non-recordable noop span).
//
// When tracing is disabled all spans are noopSpans; these spans aren't
// capable of recording, so this option should be passed to StartSpan if the
Expand Down
11 changes: 5 additions & 6 deletions pkg/util/tracing/span_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ import (
)

func TestStartSpan(t *testing.T) {
tr := NewTracer()
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeOnDemand))
sp := tr.StartSpan("test")
defer sp.Finish()
require.Equal(t, "noop", sp.OperationName())
Expand Down Expand Up @@ -393,9 +393,9 @@ func (tr *explodyNetTr) Finish() {
//
// https://github.com/cockroachdb/cockroach/issues/58489#issuecomment-781263005
func TestSpan_UseAfterFinish(t *testing.T) {
tr := NewTracer()
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeActiveSpansRegistry))
tr._useNetTrace = 1
sp := tr.StartSpan("foo", WithForceRealSpan())
sp := tr.StartSpan("foo")
require.NotNil(t, sp.i.netTr)
// Set up netTr to reliably explode if Finish'ed twice. We
// expect `sp.Finish` to not let it come to that.
Expand Down Expand Up @@ -444,12 +444,11 @@ func (i *countingStringer) String() string {
// TestSpanTagsInRecordings verifies that tags added before a recording started
// are part of the recording.
func TestSpanTagsInRecordings(t *testing.T) {
tr := NewTracer()
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeActiveSpansRegistry))
var counter countingStringer
logTags := logtags.SingleTagBuffer("foo", "tagbar")
logTags = logTags.Add("foo1", &counter)
sp := tr.StartSpan("root",
WithForceRealSpan(),
WithLogTags(logTags),
)
defer sp.Finish()
Expand Down Expand Up @@ -487,7 +486,7 @@ func TestStructureRecording(t *testing.T) {
t.Run(fmt.Sprintf("finish1=%t", finishCh1), func(t *testing.T) {
for _, finishCh2 := range []bool{true, false} {
t.Run(fmt.Sprintf("finish2=%t", finishCh2), func(t *testing.T) {
tr := NewTracerWithOpt(context.Background(), WithTestingKnobs(TracerTestingKnobs{ForceRealSpans: true}))
tr := NewTracerWithOpt(context.Background(), WithTracingMode(TracingModeActiveSpansRegistry))
sp := tr.StartSpan("root", WithRecording(RecordingStructured))
ch1 := tr.StartSpan("child", WithParent(sp))
ch2 := tr.StartSpan("grandchild", WithParent(ch1))
Expand Down
Loading