From 36992b3c6bfeeabac77ea86db981eb8e878ce21d Mon Sep 17 00:00:00 2001 From: irfan sharif Date: Mon, 11 Jan 2021 12:12:36 -0500 Subject: [PATCH] tracing,bench: introduce BenchmarkTracing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit BenchmarkTracing measures the overhead of always-on tracing. It also reports the memory utilization. make bench PKG=./pkg/bench \ TESTFLAGS='-benchtime=5000x -count 20' \ BENCHES='BenchmarkTracing' BENCHTIMEOUT=50m Plumbing that into `benchstat` (old is without always-on tracing, new is with): name old time/op new time/op delta Tracing/Cockroach/tracing=x/Scan1-16 172µs ± 2% 164µs ± 4% -4.87% (p=0.000 n=17+19) Tracing/Cockroach/tracing=x/Insert-16 253µs ± 5% 249µs ± 5% -1.68% (p=0.028 n=19+20) Tracing/MultinodeCockroach/tracing=x/Scan1-16 413µs ± 5% 491µs ±30% +18.89% (p=0.000 n=19+20) Tracing/MultinodeCockroach/tracing=x/Insert-16 543µs ±12% 539µs ± 7% ~ (p=0.925 n=20+20) name old alloc/op new alloc/op delta Tracing/Cockroach/tracing=x/Scan1-16 23.0kB ± 0% 23.3kB ± 2% +0.95% (p=0.000 n=17+17) Tracing/Cockroach/tracing=x/Insert-16 38.7kB ±21% 38.1kB ± 7% ~ (p=0.687 n=20+19) Tracing/MultinodeCockroach/tracing=x/Scan1-16 72.0kB ±15% 75.1kB ±10% +4.28% (p=0.000 n=19+20) Tracing/MultinodeCockroach/tracing=x/Insert-16 102kB ±19% 101kB ±11% ~ (p=0.813 n=20+19) name old allocs/op new allocs/op delta Tracing/Cockroach/tracing=x/Scan1-16 247 ± 0% 248 ± 1% +0.21% (p=0.004 n=16+17) Tracing/Cockroach/tracing=x/Insert-16 309 ± 0% 310 ± 2% ~ (p=0.059 n=17+20) Tracing/MultinodeCockroach/tracing=x/Scan1-16 762 ± 3% 766 ± 3% +0.58% (p=0.015 n=17+19) Tracing/MultinodeCockroach/tracing=x/Insert-16 734 ± 3% 733 ± 2% ~ (p=0.402 n=19+19) Release note: None --- pkg/bench/bench_test.go | 51 ++++++++++++++++++++++++++ pkg/server/node.go | 1 - pkg/sql/colflow/vectorized_flow.go | 2 +- pkg/sql/conn_executor_exec.go | 2 +- pkg/sql/tests/kv_test.go | 57 ++++++++++++++++++++++++++++++ pkg/util/tracing/tracer.go | 2 +- 6 files changed, 111 insertions(+), 4 deletions(-) diff --git a/pkg/bench/bench_test.go b/pkg/bench/bench_test.go index 113faafa93e0..320cd2af6eb9 100644 --- a/pkg/bench/bench_test.go +++ b/pkg/bench/bench_test.go @@ -400,6 +400,53 @@ func BenchmarkSQL(b *testing.B) { }) } +// BenchmarkTracing measures the overhead of always-on tracing. It also reports +// the memory utilization. +// +// TODO(irfansharif): This benchmark is only useful while we transition between +// the legacy trace.mode, and the "always-on" mode introduced in 21.1. We can +// remove it in 21.2. +func BenchmarkTracing(b *testing.B) { + skip.UnderShort(b) + defer log.Scope(b).Close(b) + + for _, dbFn := range []func(*testing.B, BenchmarkFn){ + benchmarkCockroach, + benchmarkMultinodeCockroach, + } { + dbName := runtime.FuncForPC(reflect.ValueOf(dbFn).Pointer()).Name() + dbName = strings.TrimPrefix(dbName, "github.com/cockroachdb/cockroach/pkg/bench.benchmark") + + b.Run(dbName, func(b *testing.B) { + dbFn(b, func(b *testing.B, db *sqlutils.SQLRunner) { + for _, tracingEnabled := range []bool{true, false} { + var tracingMode string + if tracingEnabled { + tracingMode = "background" + } else { + tracingMode = "legacy" + } + db.Exec(b, fmt.Sprintf("SET CLUSTER SETTING trace.mode = %s", tracingMode)) + b.Run(fmt.Sprintf("tracing=%s", tracingMode[:1]), func(b *testing.B) { + for _, runFn := range []func(*testing.B, *sqlutils.SQLRunner, int){ + runBenchmarkScan1, + runBenchmarkInsert, + } { + fnName := runtime.FuncForPC(reflect.ValueOf(runFn).Pointer()).Name() + fnName = strings.TrimPrefix(fnName, "github.com/cockroachdb/cockroach/pkg/bench.runBenchmark") + b.Run(fnName, func(b *testing.B) { + b.ReportAllocs() + + runFn(b, db, 1 /* count */) + }) + } + }) + } + }) + }) + } +} + // runBenchmarkUpdate benchmarks updating count random rows in a table. func runBenchmarkUpdate(b *testing.B, db *sqlutils.SQLRunner, count int) { defer func() { @@ -506,6 +553,10 @@ func runBenchmarkDelete(b *testing.B, db *sqlutils.SQLRunner, rows int) { b.StopTimer() } +func runBenchmarkScan1(b *testing.B, db *sqlutils.SQLRunner, count int) { + runBenchmarkScan(b, db, count, 1) +} + // runBenchmarkScan benchmarks scanning a table containing count rows. func runBenchmarkScan(b *testing.B, db *sqlutils.SQLRunner, count int, limit int) { defer func() { diff --git a/pkg/server/node.go b/pkg/server/node.go index 18999d08a6e4..f623dd125a76 100644 --- a/pkg/server/node.go +++ b/pkg/server/node.go @@ -959,7 +959,6 @@ func (n *Node) setupSpanForIncomingRPC( if br == nil { return } - // TODO(irfansharif): How come this span is never Finish()-ed? #58721. if grpcSpan != nil { // If our local span descends from a parent on the other // end of the RPC (i.e. the !isLocalRequest) case, diff --git a/pkg/sql/colflow/vectorized_flow.go b/pkg/sql/colflow/vectorized_flow.go index e2f49794d49f..a6bf3fa9eac3 100644 --- a/pkg/sql/colflow/vectorized_flow.go +++ b/pkg/sql/colflow/vectorized_flow.go @@ -947,7 +947,6 @@ func (s *vectorizedFlowCreator) setupOutput( // Start a separate recording so that GetRecording will return // the recordings for only the child spans containing stats. ctx, span := tracing.ChildSpanRemote(ctx, "") - // TODO(irfansharif): How come this span is never Finish()-ed? #58721. if atomic.AddInt32(&s.numOutboxesDrained, 1) == atomic.LoadInt32(&s.numOutboxes) { // At the last outbox, we can accurately retrieve stats for the // whole flow from parent monitors. These stats are added to a @@ -965,6 +964,7 @@ func (s *vectorizedFlowCreator) setupOutput( }) } finishVectorizedStatsCollectors(ctx, vscs) + span.Finish() return []execinfrapb.ProducerMetadata{{TraceData: span.GetRecording()}} }, }, diff --git a/pkg/sql/conn_executor_exec.go b/pkg/sql/conn_executor_exec.go index 69d257a67263..8b7546ec2103 100644 --- a/pkg/sql/conn_executor_exec.go +++ b/pkg/sql/conn_executor_exec.go @@ -636,7 +636,6 @@ func (ex *connExecutor) execStmtInOpenState( if !alreadyRecording && stmtTraceThreshold > 0 { ctx, stmtThresholdSpan = createRootOrChildSpan(ctx, "trace-stmt-threshold", ex.transitionCtx.tracer) stmtThresholdSpan.SetVerbose(true) - // TODO(irfansharif): How come this span is never Finish()-ed? #58721. } if err := ex.dispatchToExecutionEngine(ctx, p, res); err != nil { @@ -644,6 +643,7 @@ func (ex *connExecutor) execStmtInOpenState( } if stmtThresholdSpan != nil { + stmtThresholdSpan.Finish() logTraceAboveThreshold( ctx, stmtThresholdSpan.GetRecording(), diff --git a/pkg/sql/tests/kv_test.go b/pkg/sql/tests/kv_test.go index 3e81894fa3f1..85ca1b0cd04d 100644 --- a/pkg/sql/tests/kv_test.go +++ b/pkg/sql/tests/kv_test.go @@ -24,6 +24,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/base" kv2 "github.com/cockroachdb/cockroach/pkg/kv" "github.com/cockroachdb/cockroach/pkg/testutils/serverutils" + "github.com/cockroachdb/cockroach/pkg/util/log" "github.com/cockroachdb/errors" ) @@ -148,12 +149,26 @@ type kvSQL struct { } func newKVSQL(b *testing.B) kvInterface { + return newKVSQLWithTracing(b, false) +} + +func newKVSQLWithTracing(b *testing.B, enabled bool) kvInterface { s, db, _ := serverutils.StartServer(b, base.TestServerArgs{UseDatabase: "bench"}) if _, err := db.Exec(`CREATE DATABASE IF NOT EXISTS bench`); err != nil { b.Fatal(err) } + var tracingMode string + if enabled { + tracingMode = "background" + } else { + tracingMode = "legacy" + } + if _, err := db.Exec(fmt.Sprintf("SET CLUSTER SETTING trace.mode = %s", tracingMode)); err != nil { + b.Fatal(err) + } + kv := &kvSQL{} kv.db = db kv.doneFn = func() { @@ -297,3 +312,45 @@ func BenchmarkKV(b *testing.B) { }) } } + +func BenchmarkTracing(b *testing.B) { + defer log.Scope(b).Close(b) + + for i, opFn := range []func(kvInterface, int, int) error{ + kvInterface.Insert, + kvInterface.Update, + kvInterface.Delete, + kvInterface.Scan, + } { + opName := runtime.FuncForPC(reflect.ValueOf(opFn).Pointer()).Name() + opName = strings.TrimPrefix(opName, "github.com/cockroachdb/cockroach/pkg/sql/tests_test.kvInterface.") + for _, tracingEnabled := range []bool{true, false} { + var trace = "f" + if tracingEnabled { + trace = "t" + } + + for _, rows := range []int{1, 10, 100, 1000, 10000} { + b.Run(fmt.Sprintf("tracing=%s/%s/rows=%d", trace, opName, rows), func(b *testing.B) { + + b.ReportAllocs() + + kv := newKVSQLWithTracing(b, tracingEnabled) + defer kv.done() + + if err := kv.prep(rows, i != 0 /* Insert */ && i != 2 /* Delete */); err != nil { + b.Fatal(err) + } + + b.ResetTimer() + for i := 0; i < b.N; i++ { + if err := opFn(kv, rows, i); err != nil { + b.Fatal(err) + } + } + b.StopTimer() + }) + } + } + } +} diff --git a/pkg/util/tracing/tracer.go b/pkg/util/tracing/tracer.go index 9737c2638fb5..6782151126ce 100644 --- a/pkg/util/tracing/tracer.go +++ b/pkg/util/tracing/tracer.go @@ -263,7 +263,7 @@ func (t *Tracer) AlwaysTrace() bool { // startSpanGeneric is the implementation of StartSpanCtx and StartSpan. In // the latter case, ctx == noCtx and the returned Context is the supplied one; -// otherwise the returned Context reflects the returned Span. +// otherwise the returned Context embeds the returned Span. func (t *Tracer) startSpanGeneric( ctx context.Context, opName string, opts spanOptions, ) (context.Context, *Span) {