Merge #56109

56109: tracing: rework StartSpan API r=RaduBerinde a=tbg

The tracer previously offered three APIs for starting spans. First, there was `StartSpan`, mandated by the `opentracing` interfaces, which was unnecessarily allocation-heavy, in particular when the caller was holding on to a span directly (rather than having received information about a parent span from the RPC). Offsetting the inefficiencies, we had added two separate methods, `StartRootSpan` and `StartChildSpan`, that took in various options directly (and which were not conforming to the `opentracing` specs). These latter two in particular had become a hodge podge of settings that were added organically over time.

Now, with the opentracing interfaces out of the picture, it was time to make some clarifications. The key change in this PR is that StartSpan now becomes the *only* way to start traces, and allows doing so efficiently in all cases. In particular, we provide two separate options that specify a parent span:

- `WithParent`, for the case in which the caller has a `*Span` at their disposal, i.e. we're creating a new trace span locally, and
- `WithRemoteParent`, for the case in which a span is to be derived from metadata about a parent span on the other side of an RPC.

The implementations are now deliberate about which case they're in, which I have found greatly helps the clarity of the implementation. In particular, `*SpanContext`, which was previously used for both local and remote parents, and as a result was only partially populated in the remote case, now only contains the fields corresponding to data coming in over the wire, and is only ever used in the remote case. Reflecting this, it was renamed to `RemoteSpan`. Its usage has decreased dramatically due to the `WithParent` option, with only a single call site to `WithRemoteParent` remaining outside of the `tracing` package (to propagate trace information on the Raft streams, something difficult to wrap in an RPC middleware due to batching).

The explicit distinction between remote and local parents has also clarified the current semantics of recording inheritance. Remember that (explicit opt-out aside) a child span created from a local parent shares its recording with that parent (which transitively shares with any local grandparent). "Obviously" this does not work across RPC boundaries without an additional mechanism to feed the spans back into the caller's span, but in the old API there really wasn't an obvious way to simulate the "remote" case (since calling `.Context()` on a local span and deriving from that locally would correspond to what is now `WithParent(span)`, i.e. the local case). Now, in tests such as `TestRecordingInRecording`, we clearly see the distinction in behavior.
As an aside, the current thinking is to do away with the concept of sharing recordings and also the concept of inserting a recording into an existing span. Instead, we will endow the tracer with a registry that is handed any recordings received from remote RPCs. The registry is in charge of maintaining the partial trace tree and releasing it the moment the local span is `Finished()`, and allows retrieving the aggregate recording before this point in time. This is both conceptually simpler (spans never share recordings, so in particular the knob to control the behavior goes away), and also allows for straightforward generalizations towards true distributed tracing.

The `Recordable` option was renamed to `WithForceRealSpan` for clarity. While technically the old name was apt, the dichotomy between noopSpan vs recordable span has been hard for me to internalize and I assume this holds for others as well. "real span" vs "noop span" is a more natural dichotomy to remember. Of course, ultimately the goal of moving to always-on tracing means that the concept of a noop span goes away (or at least stops being the case to optimize for), so more changes here will take place in the future.

There is still cruft in the interfaces, but with PR we're within striking distance and will be able to adapt the semantics to the requirements of always-on tracing soon.

Also, we are probably allocating more than we were before. However,
there's nothing we can't fix. I am planning to polish #54738 soon
and carry out a first round of improvements within.

Release note: None

Co-authored-by: Tobias Grieger <[email protected]>

pkg/cli/start.go

@@ -322,7 +322,7 @@ func runStart(cmd *cobra.Command, args []string, startSingleNode bool) error {
 	// has completed.
 	// TODO(andrei): we don't close the span on the early returns below.
 	tracer := serverCfg.Settings.Tracer
-	sp := tracer.StartRootSpan("server start", nil /* logTags */, tracing.NonRecordableSpan)
+	sp := tracer.StartSpan("server start")
 	ctx = tracing.ContextWithSpan(ctx, sp)
 
 	// Set up the logging and profiling output.

pkg/kv/kvclient/kvcoord/transport_test.go

@@ -144,7 +144,7 @@ var _ roachpb.InternalClient = &mockInternalClient{}
 func (m *mockInternalClient) Batch(
 	ctx context.Context, in *roachpb.BatchRequest, opts ...grpc.CallOption,
 ) (*roachpb.BatchResponse, error) {
-	sp := m.tr.StartRootSpan("mock", nil /* logTags */, tracing.RecordableSpan)
+	sp := m.tr.StartSpan("mock", tracing.WithForceRealSpan())
 	defer sp.Finish()
 	sp.StartRecording(tracing.SnowballRecording)
 	ctx = tracing.ContextWithSpan(ctx, sp)

pkg/kv/kvclient/kvcoord/txn_coord_sender_server_test.go

@@ -151,7 +151,7 @@ func TestNoDuplicateHeartbeatLoops(t *testing.T) {
 	key := roachpb.Key("a")
 
 	tracer := tracing.NewTracer()
-	sp := tracer.StartSpan("test", tracing.Recordable)
+	sp := tracer.StartSpan("test", tracing.WithForceRealSpan())
 	sp.StartRecording(tracing.SingleNodeRecording)
 	txnCtx := tracing.ContextWithSpan(context.Background(), sp)
 

pkg/kv/kvserver/batcheval/BUILD.bazel

@@ -75,7 +75,6 @@ go_library(
         "//pkg/util/tracing",
         "//pkg/util/uuid",
         "//vendor/github.com/cockroachdb/errors",
-        "//vendor/github.com/cockroachdb/logtags",
         "//vendor/github.com/kr/pretty",
         "//vendor/golang.org/x/time/rate",
     ],

pkg/kv/kvserver/batcheval/cmd_end_transaction.go

@@ -33,7 +33,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/errors"
-	"github.com/cockroachdb/logtags"
 )
 
 func init() {
@@ -812,9 +811,7 @@ func splitTrigger(
 	ts hlc.Timestamp,
 ) (enginepb.MVCCStats, result.Result, error) {
 	// TODO(andrei): should this span be a child of the ctx's (if any)?
-	sp := rec.ClusterSettings().Tracer.StartRootSpan(
-		"split", logtags.FromContext(ctx), tracing.NonRecordableSpan,
-	)
+	sp := rec.ClusterSettings().Tracer.StartSpan("split", tracing.WithCtxLogTags(ctx))
 	defer sp.Finish()
 	desc := rec.Desc()
 	if !bytes.Equal(desc.StartKey, split.LeftDesc.StartKey) ||

pkg/kv/kvserver/replica_application_decoder.go

@@ -143,14 +143,14 @@ func (d *replicaDecoder) createTracingSpans(ctx context.Context) {
 			cmd.ctx, cmd.sp = tracing.ForkCtxSpan(cmd.proposal.ctx, opName)
 		} else if cmd.raftCmd.TraceData != nil {
 			// The proposal isn't local, and trace data is available. Extract
-			// the span context and start a server-side span.
+			// the remote span and start a server-side span that follows from it.
 			spanCtx, err := d.r.AmbientContext.Tracer.Extract(
 				opentracing.TextMap, opentracing.TextMapCarrier(cmd.raftCmd.TraceData))
 			if err != nil {
 				log.Errorf(ctx, "unable to extract trace data from raft command: %s", err)
 			} else {
 				cmd.sp = d.r.AmbientContext.Tracer.StartSpan(
-					"raft application", opentracing.FollowsFrom(spanCtx))
+					"raft application", tracing.WithRemoteParent(spanCtx), tracing.WithFollowsFrom())
 				cmd.ctx = tracing.ContextWithSpan(ctx, cmd.sp)
 			}
 		} else {

pkg/kv/kvserver/replica_proposal.go

@@ -885,7 +885,7 @@ func (r *Replica) requestToProposal(
 	return proposal, pErr
 }
 
-// getTraceData extracts the SpanContext of the current span.
+// getTraceData extracts the SpanMeta of the current span.
 func (r *Replica) getTraceData(ctx context.Context) opentracing.TextMapCarrier {
 	sp := tracing.SpanFromContext(ctx)
 	if sp == nil {
@@ -896,9 +896,9 @@ func (r *Replica) getTraceData(ctx context.Context) opentracing.TextMapCarrier {
 	}
 	traceData := opentracing.TextMapCarrier{}
 	if err := r.AmbientContext.Tracer.Inject(
-		sp.Context(), opentracing.TextMap, traceData,
+		sp.Meta(), opentracing.TextMap, traceData,
 	); err != nil {
-		log.Errorf(ctx, "failed to inject sp context (%+v) as trace data: %s", sp.Context(), err)
+		log.Errorf(ctx, "failed to inject sp context (%+v) as trace data: %s", sp.Meta(), err)
 		return nil
 	}
 	return traceData

pkg/kv/kvserver/replica_range_lease.go

@@ -56,8 +56,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/errors"
-	"github.com/cockroachdb/logtags"
-	"github.com/opentracing/opentracing-go"
 	"go.etcd.io/etcd/raft"
 )
 
@@ -297,12 +295,12 @@ func (p *pendingLeaseRequest) requestLeaseAsync(
 		// except that one does not currently support FollowsFrom relationships.
 		sp = tr.StartSpan(
 			opName,
-			opentracing.FollowsFrom(parentSp.Context()),
-			tracing.LogTagsFromCtx(parentCtx),
+			tracing.WithParent(parentSp),
+			tracing.WithFollowsFrom(),
+			tracing.WithCtxLogTags(parentCtx),
 		)
 	} else {
-		sp = tr.StartRootSpan(
-			opName, logtags.FromContext(parentCtx), tracing.NonRecordableSpan)
+		sp = tr.StartSpan(opName, tracing.WithCtxLogTags(parentCtx))
 	}
 
 	// Create a new context *without* a timeout. Instead, we multiplex the

pkg/kv/kvserver/replica_test.go

@@ -12557,7 +12557,7 @@ func TestLaterReproposalsDoNotReuseContext(t *testing.T) {
 
 	// Hold the RaftLock to encourage the reproposals to occur in the same batch.
 	tc.repl.RaftLock()
-	sp := tracer.StartRootSpan("replica send", logtags.FromContext(ctx), tracing.RecordableSpan)
+	sp := tracer.StartSpan("replica send", tracing.WithCtxLogTags(ctx), tracing.WithForceRealSpan())
 	tracedCtx := tracing.ContextWithSpan(ctx, sp)
 	// Go out of our way to enable recording so that expensive logging is enabled
 	// for this context.

pkg/server/node.go

@@ -979,8 +979,8 @@ func (n *Node) setupSpanForIncomingRPC(
 			// If tracing information was passed via gRPC metadata, the gRPC interceptor
 			// should have opened a span for us. If not, open a span now (if tracing is
 			// disabled, this will be a noop span).
-			newSpan = n.storeCfg.AmbientCtx.Tracer.StartRootSpan(
-				opName, n.storeCfg.AmbientCtx.LogTags(), tracing.NonRecordableSpan,
+			newSpan = n.storeCfg.AmbientCtx.Tracer.StartSpan(
+				opName, tracing.WithLogTags(n.storeCfg.AmbientCtx.LogTags()),
 			)
 			ctx = tracing.ContextWithSpan(ctx, newSpan)
 		} else {

pkg/sql/BUILD.bazel

@@ -357,7 +357,6 @@ go_library(
         "//vendor/github.com/gogo/protobuf/proto",
         "//vendor/github.com/lib/pq",
         "//vendor/github.com/lib/pq/oid",
-        "//vendor/github.com/opentracing/opentracing-go",
         "//vendor/github.com/prometheus/client_model/go",
         "//vendor/golang.org/x/net/trace",
         "//vendor/golang.org/x/text/collate",

pkg/sql/distsql/BUILD.bazel

@@ -30,9 +30,7 @@ go_library(
         "//pkg/util/timeutil",
         "//pkg/util/tracing",
         "//vendor/github.com/cockroachdb/errors",
-        "//vendor/github.com/cockroachdb/logtags",
         "//vendor/github.com/cockroachdb/redact",
-        "//vendor/github.com/opentracing/opentracing-go",
     ],
 )
 

pkg/sql/distsql/server.go

@@ -40,9 +40,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/errors"
-	"github.com/cockroachdb/logtags"
 	"github.com/cockroachdb/redact"
-	"github.com/opentracing/opentracing-go"
 )
 
 // minFlowDrainWait is the minimum amount of time a draining server allows for
@@ -197,26 +195,21 @@ func (ds *ServerImpl) setupFlow(
 	const opName = "flow"
 	var sp *tracing.Span
 	if parentSpan == nil {
-		sp = ds.Tracer.StartRootSpan(
-			opName, logtags.FromContext(ctx), tracing.NonRecordableSpan)
+		sp = ds.Tracer.StartSpan(opName, tracing.WithCtxLogTags(ctx))
 	} else if localState.IsLocal {
 		// If we're a local flow, we don't need a "follows from" relationship: we're
 		// going to run this flow synchronously.
 		// TODO(andrei): localState.IsLocal is not quite the right thing to use.
 		//  If that field is unset, we might still want to create a child span if
 		//  this flow is run synchronously.
-		sp = ds.Tracer.StartChildSpan(
-			opName, parentSpan.SpanContext(), logtags.FromContext(ctx), tracing.NonRecordableSpan,
-			false /* separateRecording */)
+		sp = ds.Tracer.StartSpan(opName, tracing.WithParent(parentSpan), tracing.WithCtxLogTags(ctx))
 	} else {
 		// We use FollowsFrom because the flow's span outlives the SetupFlow request.
-		// TODO(andrei): We should use something more efficient than StartSpan; we
-		// should use AmbientContext.AnnotateCtxWithSpan() but that interface
-		// doesn't currently support FollowsFrom relationships.
 		sp = ds.Tracer.StartSpan(
 			opName,
-			opentracing.FollowsFrom(parentSpan.Context()),
-			tracing.LogTagsFromCtx(ctx),
+			tracing.WithParent(parentSpan),
+			tracing.WithFollowsFrom(),
+			tracing.WithCtxLogTags(ctx),
 		)
 	}
 	// sp will be Finish()ed by Flow.Cleanup().

pkg/sql/exec_util.go

@@ -73,7 +73,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
 	"github.com/cockroachdb/errors"
-	"github.com/opentracing/opentracing-go"
 )
 
 // ClusterOrganization is the organization name.
@@ -1522,21 +1521,19 @@ func (st *SessionTracing) StartTracing(
 	var sp *tracing.Span
 	connCtx := st.ex.ctxHolder.connCtx
 
-	// TODO(andrei): use tracing.EnsureChildSpan() or something more efficient
-	// than StartSpan(). The problem is that the current interface doesn't allow
-	// the Recordable option to be passed.
 	if parentSp := tracing.SpanFromContext(connCtx); parentSp != nil {
 		// Create a child span while recording.
 		sp = parentSp.Tracer().StartSpan(
 			opName,
-			opentracing.ChildOf(parentSp.Context()), tracing.Recordable,
-			tracing.LogTagsFromCtx(connCtx),
+			tracing.WithParent(parentSp),
+			tracing.WithCtxLogTags(connCtx),
+			tracing.WithForceRealSpan(),
 		)
 	} else {
 		// Create a root span while recording.
 		sp = st.ex.server.cfg.AmbientCtx.Tracer.StartSpan(
-			opName, tracing.Recordable,
-			tracing.LogTagsFromCtx(connCtx),
+			opName, tracing.WithForceRealSpan(),
+			tracing.WithCtxLogTags(connCtx),
 		)
 	}
 	sp.StartRecording(recType)

pkg/sql/explain_distsql.go

@@ -21,7 +21,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/hlc"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/errors"
-	"github.com/opentracing/opentracing-go"
 )
 
 // explainDistSQLNode is a planNode that wraps a plan and returns
@@ -168,14 +167,14 @@ func (n *explainDistSQLNode) startExec(params runParams) error {
 			!parentSp.IsRecording() {
 			tracer := parentSp.Tracer()
 			sp = tracer.StartSpan(
-				"explain-distsql", tracing.Recordable,
-				opentracing.ChildOf(parentSp.Context()),
-				tracing.LogTagsFromCtx(params.ctx))
+				"explain-distsql", tracing.WithForceRealSpan(),
+				tracing.WithParent(parentSp),
+				tracing.WithCtxLogTags(params.ctx))
 		} else {
 			tracer := params.extendedEvalCtx.ExecCfg.AmbientCtx.Tracer
 			sp = tracer.StartSpan(
-				"explain-distsql", tracing.Recordable,
-				tracing.LogTagsFromCtx(params.ctx))
+				"explain-distsql", tracing.WithForceRealSpan(),
+				tracing.WithCtxLogTags(params.ctx))
 		}
 		sp.StartRecording(tracing.SnowballRecording)
 		ctx := tracing.ContextWithSpan(params.ctx, sp)

pkg/sql/rowexec/tablereader_test.go

@@ -392,7 +392,7 @@ func TestLimitScans(t *testing.T) {
 
 	// Now we're going to run the tableReader and trace it.
 	tracer := tracing.NewTracer()
-	sp := tracer.StartSpan("root", tracing.Recordable)
+	sp := tracer.StartSpan("root", tracing.WithForceRealSpan())
 	sp.StartRecording(tracing.SnowballRecording)
 	ctx = tracing.ContextWithSpan(ctx, sp)
 	flowCtx.EvalCtx.Context = ctx

pkg/sql/rowflow/routers_test.go

@@ -752,7 +752,7 @@ func TestRouterDiskSpill(t *testing.T) {
 
 	// Enable stats recording.
 	tracer := tracing.NewTracer()
-	sp := tracer.StartSpan("root", tracing.Recordable)
+	sp := tracer.StartSpan("root", tracing.WithForceRealSpan())
 	sp.StartRecording(tracing.SnowballRecording)
 	ctx := tracing.ContextWithSpan(context.Background(), sp)
 

pkg/sql/txn_state.go

@@ -27,8 +27,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/errors"
-	"github.com/cockroachdb/logtags"
-	opentracing "github.com/opentracing/opentracing-go"
 )
 
 // txnState contains state associated with an ongoing SQL txn; it constitutes
@@ -162,24 +160,20 @@ func (ts *txnState) resetForNewSQLTxn(
 	var sp *tracing.Span
 	opName := sqlTxnName
 
-	// Create a span for the new txn. The span is always Recordable to support the
+	// Create a span for the new txn. The span is always WithForceRealSpan to support the
 	// use of session tracing, which may start recording on it.
-	// TODO(andrei): We should use tracing.EnsureChildSpan() as that's much more
-	// efficient that StartSpan (and also it'd be simpler), but that interface
-	// doesn't current support the Recordable option.
 	if parentSp := tracing.SpanFromContext(connCtx); parentSp != nil {
 		// Create a child span for this SQL txn.
 		sp = parentSp.Tracer().StartSpan(
 			opName,
-			opentracing.ChildOf(parentSp.Context()), tracing.Recordable,
-			tracing.LogTagsFromCtx(connCtx),
+			tracing.WithParent(parentSp),
+			tracing.WithCtxLogTags(connCtx),
+			tracing.WithForceRealSpan(),
 		)
 	} else {
 		// Create a root span for this SQL txn.
-		// TODO(tbg): this is the only use of RecordableSpan. Can we instead interchange
-		// the span when we decide that it needs to be traced?
-		sp = tranCtx.tracer.StartRootSpan(
-			opName, logtags.FromContext(connCtx), tracing.RecordableSpan)
+		sp = tranCtx.tracer.StartSpan(
+			opName, tracing.WithCtxLogTags(connCtx), tracing.WithForceRealSpan())
 	}
 
 	if txnType == implicitTxn {

pkg/util/log/ambient_context_test.go

@@ -47,7 +47,7 @@ func TestAnnotateCtxSpan(t *testing.T) {
 
 	// Annotate a context that has an open span.
 
-	sp1 := tracer.StartRootSpan("root", nil /* logTags */, tracing.RecordableSpan)
+	sp1 := tracer.StartSpan("root", tracing.WithForceRealSpan())
 	sp1.StartRecording(tracing.SingleNodeRecording)
 	ctx1 := tracing.ContextWithSpan(context.Background(), sp1)
 	Event(ctx1, "a")

pkg/util/log/trace_test.go

@@ -65,7 +65,7 @@ func TestTrace(t *testing.T) {
 	Event(ctx, "should-not-show-up")
 
 	tracer := tracing.NewTracer()
-	sp := tracer.StartRootSpan("s", nil /* logTags */, tracing.RecordableSpan)
+	sp := tracer.StartSpan("s", tracing.WithForceRealSpan())
 	sp.StartRecording(tracing.SingleNodeRecording)
 	ctxWithSpan := tracing.ContextWithSpan(ctx, sp)
 	Event(ctxWithSpan, "test1")
@@ -94,7 +94,7 @@ func TestTraceWithTags(t *testing.T) {
 	ctx = logtags.AddTag(ctx, "tag", 1)
 
 	tracer := tracing.NewTracer()
-	sp := tracer.StartRootSpan("s", nil /* logTags */, tracing.RecordableSpan)
+	sp := tracer.StartSpan("s", tracing.WithForceRealSpan())
 	ctxWithSpan := tracing.ContextWithSpan(ctx, sp)
 	sp.StartRecording(tracing.SingleNodeRecording)
 
@@ -180,7 +180,7 @@ func TestEventLogAndTrace(t *testing.T) {
 	VErrEvent(ctxWithEventLog, noLogV(), "testerr")
 
 	tracer := tracing.NewTracer()
-	sp := tracer.StartRootSpan("s", nil /* logTags */, tracing.RecordableSpan)
+	sp := tracer.StartSpan("s", tracing.WithForceRealSpan())
 	sp.StartRecording(tracing.SingleNodeRecording)
 	ctxWithBoth := tracing.ContextWithSpan(ctxWithEventLog, sp)
 	// Events should only go to the trace.

pkg/util/tracing/BUILD.bazel

@@ -9,6 +9,7 @@ go_library(
         "recording.go",
         "shadow.go",
         "span.go",
+        "span_options.go",
         "tags.go",
         "test_utils.go",
         "tracer.go",