cockroachdb / cockroachdb/cockroach
util/tracing: colliding span IDs make Recording formatting take exponential time
- Dominant language
- Go
- Stars
- 32.5k
- Forks
- 4.1k
- PR merge metrics
- PR metrics pending
Description
**Describe the problem**
Two defects that compound:
1. `singleflight` grafts a copy of a flight's trace onto every non-leader waiter ([singleflight.go:281](https://github.com/cockroachdb/cockroach/blob/8812064a015d/pkg/util/syncutil/singleflight/singleflight.go#L281)), and `Trace.PartialClone` deep-copies the spans **without re-generating span IDs**.
2. `Recording.visitSpanWithWriter` reconstructs the tree purely from IDs, scanning for `osp.ParentSpanID == sp.SpanID` ([recording.go:436](https://github.com/cockroachdb/cockroach/blob/8812064a015d/pkg/util/tracing/tracingpb/recording.go#L436)), so a span ID present *k* times has its subtree walked *k* times — compounding per level, i.e. k^depth paths.
Normally the waiter is in a *different* trace than the leader, so the reused IDs are never visible in one recording. When leader and waiter share a trace, the flight's subtree lands in the `Recording` k times with identical IDs at every level, and `Recording.String()` blows up.
The flight span is created as an ordinary child of the leader ([singleflight.go:345](https://github.com/cockroachdb/cockroach/blob/8812064a015d/pkg/util/syncutil/singleflight/singleflight.go#L345)), so the leader already has a natural copy; each waiter adds another. Only the imported root is reparented — everything below keeps its original `ParentSpanID`:
```
root
├── A (leader) └── B (waiter)
│ └── SpanID X, parent A └── SpanID X, parent B
│ └── SpanID Y, parent X └── SpanID Y, parent X
│ └── SpanID Z, parent Y └── SpanID Z, parent Y
```
Walking from `A`: children of `X` matches **both** `Y`s, children of each `Y` matches both `Z`s. Once the walker steps below an imported root it cannot tell which copy it is in, so it explores all of them at every level.
**To Reproduce**
One leader and two waiters under a common root produce 13 spans with only 7 distinct IDs:
```
span ID 8130299822892713557 appears 3 times: [flight flight flight]
span ID 2365963628973175211 appears 3 times: [flight-child-1 flight-child-1 flight-child-1]
span ID 3995509870355044888 appears 3 times: [flight-child-2 flight-child-2 flight-child-2]
```
repro test (pkg/util/syncutil/singleflight)
```go
func TestSingleflightDuplicateSpanIDs(t *testing.T) {
tr := tracing.NewTracer()
ctx, getRec := tracing.ContextWithRecordingSpan(context.Background(), tr, "root")
g := NewGroup("flight", "key")
release, started := make(chan struct{}), make(chan struct{})
ctxA, spA := tracing.ChildSpan(ctx, "A")
futA, isLeader := g.DoChan(ctxA, "k", DoOpts{}, func(ctx context.Context) (interface{}, error) {
_, sp1 := tracing.ChildSpan(ctx, "flight-child-1")
_, sp2 := tracing.ChildSpan(tracing.ContextWithSpan(ctx, sp1), "flight-child-2")
close(started)
<-release
sp2.Finish()
sp1.Finish()
return nil, nil
})
require.True(t, isLeader)
<-started
ctxB, spB := tracing.ChildSpan(ctx, "B")
futB, _ := g.DoChan(ctxB, "k", DoOpts{}, func(context.Context) (interface{}, error) { return nil, nil })
ctxC, spC := tracing.ChildSpan(ctx, "C")
futC, _ := g.DoChan(ctxC, "k", DoOpts{}, func(context.Context) (interface{}, error) { return nil, nil })
close(release)
futA.WaitForResult(ctxA)
futB.WaitForResult(ctxB)
futC.WaitForResult(ctxC)
spA.Finish()
spB.Finish()
spC.Finish()
rec := getRec()
byID := map[tracingpb.SpanID][]string{}
for _, sp := range rec {
byID[sp.SpanID] = append(byID[sp.SpanID], sp.Operation)
}
t.Logf("recording has %d spans, %d distinct IDs", len(rec), len(byID))
for id, ops := range byID {
if len(ops) > 1 {
t.Logf("span ID %d appears %d times: %v", id, len(ops), ops)
}
}
}
```
Formatting cost as a function of collisions — span count is irrelevant, a *well-formed* 865-span recording formats in 19 ms and a degenerate 865-span chain in 281 ms:
| shape | spans | `String()` |
|---|---|---|
| 12 levels × 2 copies | 25 | 176 ms |
| 12 levels × 3 copies | 37 | **18 s, 40 GiB allocated** |
| 12 levels × 4 copies | 49 | **unfinished at 30 s, 165 GiB and climbing** |
**Expected behavior**
- A `Recording` should not contain two spans with the same ID.
- Formatting any `Recording` should be bounded regardless — today a malformed one hangs the caller and grows the heap without limit.
**Additional context**
Observed as #173888: a `kvnemesis` worker spent 8+ minutes in `trace.String()` on an 865-span recording while node RSS climbed 4.5 → 10 GiB. `rangecache` coalesces range lookups through this exact path ([range_cache.go:244](https://github.com/cockroachdb/cockroach/blob/8812064a015d/pkg/kv/kvclient/rangecache/range_cache.go#L244)), and a wide ranged operation issues many concurrent lookups within one trace, so leader and waiters land in the same recording.
Reachable in production wherever verbose tracing is on — `SHOW TRACE`, statement diagnostics, `sql.trace.txn.enable_threshold`. Independent of the hang, the duplicated subtrees are also silently wrong in trace output today. It's probably rare to end up with these duplicate IDs though.
**Possible fixes**
1. Re-generate span IDs when importing a cloned `Trace`, or skip the import when the flight span is already an ancestor of the waiter in the same trace.
2. Bound `visitSpanWithWriter` and `treeifyRecordingInner` ([span_inner.go:112](https://github.com/cockroachdb/cockroach/blob/8812064a015d/pkg/util/tracing/span_inner.go#L112), which has the same exposure and additionally *materializes* the blowup) to visit each span at most once. Worth doing independently of (1), since it caps the damage from any source of colliding IDs.
Jira issue: CRDB-67259
Contributor guide
Research direction
Start with pkg/util/syncutil/singleflight/singleflight.go at the PartialClone import and flight-span creation, then inspect pkg/util/tracing/tracingpb/recording.go:436 and pkg/util/tracing/span_inner.go:112. Run the reproduction test described in the issue and add regression coverage for colliding IDs. Done means malformed recordings no longer cause repeated subtree expansion or unbounded formatting cost.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- distributed-systems, observability-sre
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 58/100