Skip to content

Commit 56bcc56

Browse files
committed
stop, kvclient: include DistSender partial batches in traces
Before this patch, since fairly recently, the spans created for Stopper.RunAsyncTask[Ex]() were not included in the recording of the caller's span because these spans were created with the ForkSpan(). This patch adds an option to RunAsyncEx to make the task's span a child of the caller's, and thus to be included in the caller's recording. This option is used by the DistSender when sending partial batch requests, therefore re-including these requests in higher-level traces (as they used to be). The reason why async tasks were detached from the caller's span in cockroachdb#59815 was because of concerns about parent and children spans with very different lifetimes becoming tied through a trace, delaying the garbage collection of the whole trace until the last span in it finishes. This patch gives the caller of RunAsyncTaskEx control over this behavior; in the particular case of the DistSender, the traces are not too long lived and the DistSender waits for the async tasks it spawns to finish. In such circumstances, tying the allocations of the child spans to the whole trace should be fine. Release note (general change): A recent release removed parts of some queries from the debugging traces of those queries. This information (i.e. the execution of some low-level RPCs) has been re-included in the traces.
1 parent 37cabca commit 56bcc56

4 files changed

Lines changed: 65 additions & 1 deletion

File tree

pkg/kv/kvclient/kvcoord/dist_sender.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1347,6 +1347,7 @@ func (ds *DistSender) sendPartialBatchAsync(
13471347
ctx,
13481348
stop.TaskOpts{
13491349
TaskName: "kv.DistSender: sending partial batch",
1350+
SameTrace: true,
13501351
Sem: ds.asyncSenderSem,
13511352
WaitForSem: false,
13521353
},

pkg/util/stop/BUILD.bazel

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ go_test(
3333
"//pkg/util/log",
3434
"//pkg/util/quotapool",
3535
"//pkg/util/syncutil",
36+
"//pkg/util/tracing",
3637
"@com_github_cockroachdb_errors//:errors",
3738
"@com_github_stretchr_testify//require",
3839
],

pkg/util/stop/stopper.go

Lines changed: 25 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -336,6 +336,7 @@ func (s *Stopper) RunAsyncTask(
336336
return s.RunAsyncTaskEx(ctx,
337337
TaskOpts{
338338
TaskName: taskName,
339+
SameTrace: false,
339340
Sem: nil,
340341
WaitForSem: false,
341342
},
@@ -347,6 +348,23 @@ type TaskOpts struct {
347348
// TaskName is a human-readable name for the operation. Used as the name of
348349
// the tracing span.
349350
TaskName string
351+
352+
// SameTrace, if set, makes the tracing span created for the task be a child
353+
// of the caller's span (if the caller has a span in the passed-in ctx). If
354+
// not set, the task's span is not a child span (technically, the task's span
355+
// will have a FollowsFrom relationship with the parent instead of ChildOf
356+
// relationship). When set, the recording of the parent span (if the parent is
357+
// recording) will include the child.
358+
//
359+
// Regardless of this setting, if the caller doesn't have a span, the task
360+
// doesn't get a span either.
361+
//
362+
// Setting SameTrace can have consequences on memory usage. The lifetime of
363+
// the task's span becomes tied to the lifetime of the parent. Generally
364+
// SameTrace should be used when the parent waits for the task to complete,
365+
// and the parent is not a long-running process.
366+
SameTrace bool
367+
350368
// If set, Sem is used as a semaphore limiting the concurrency (each task has
351369
// weight 1).
352370
//
@@ -403,7 +421,13 @@ func (s *Stopper) RunAsyncTaskEx(ctx context.Context, opt TaskOpts, f func(conte
403421
return ErrUnavailable
404422
}
405423

406-
ctx, span := tracing.ForkSpan(ctx, taskName)
424+
// If the caller has a span, the task gets a child span.
425+
var span *tracing.Span
426+
if opt.SameTrace {
427+
ctx, span = tracing.ChildSpan(ctx, taskName)
428+
} else {
429+
ctx, span = tracing.ForkSpan(ctx, taskName)
430+
}
407431

408432
// Call f on another goroutine.
409433
taskStarted = true // Another goroutine now takes ownership of the alloc, if any.

pkg/util/stop/stopper_test.go

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,12 @@ import (
2222
"github.com/cockroachdb/cockroach/pkg/roachpb"
2323
"github.com/cockroachdb/cockroach/pkg/testutils"
2424
"github.com/cockroachdb/cockroach/pkg/util/leaktest"
25+
"github.com/cockroachdb/cockroach/pkg/util/log"
2526
_ "github.com/cockroachdb/cockroach/pkg/util/log" // for flags
2627
"github.com/cockroachdb/cockroach/pkg/util/quotapool"
2728
"github.com/cockroachdb/cockroach/pkg/util/stop"
2829
"github.com/cockroachdb/cockroach/pkg/util/syncutil"
30+
"github.com/cockroachdb/cockroach/pkg/util/tracing"
2931
"github.com/cockroachdb/errors"
3032
"github.com/stretchr/testify/require"
3133
)
@@ -681,3 +683,39 @@ func TestCancelInCloser(t *testing.T) {
681683
type closerFunc func()
682684

683685
func (cf closerFunc) Close() { cf() }
686+
687+
// Test that task spans are included or not in the parent's recording based on
688+
// the SameTrace option.
689+
func TestStopperRunAsyncTaskTracing(t *testing.T) {
690+
defer leaktest.AfterTest(t)()
691+
s := stop.NewStopper()
692+
693+
ctx, getRecording, finish := tracing.ContextWithRecordingSpan(
694+
context.Background(), tracing.NewTracer(), "parent")
695+
696+
// Start two child tasks. Only the one with SameTrace:true is expected to be
697+
// present in the parent's recording.
698+
s.RunAsyncTaskEx(ctx, stop.TaskOpts{
699+
TaskName: "async child",
700+
SameTrace: false,
701+
},
702+
func(ctx context.Context) {
703+
log.Event(ctx, "async 1")
704+
},
705+
)
706+
s.RunAsyncTaskEx(ctx, stop.TaskOpts{
707+
TaskName: "async child same trace",
708+
SameTrace: true,
709+
},
710+
func(ctx context.Context) {
711+
log.Event(ctx, "async 2")
712+
},
713+
)
714+
715+
s.Stop(ctx)
716+
finish()
717+
require.NoError(t, tracing.TestingCheckRecordedSpans(getRecording(), `
718+
span: parent
719+
span: [async] async child same trace
720+
event: async 2`))
721+
}

0 commit comments

Comments
 (0)