Trace 4471e0a2: no root

Filed against the tracing collector, not against any of the services involved, because the services are behaving and the trace is not.

The complaint

A latency dashboard showed p99 for checkout at 41 seconds. The p50 was 81 ms. Only one trace in the window exceeded a second, and it is this one, and it is not a slow request. It is not a request.

The trace

$ traceq show 4471e0a2 --tree
[ ! ] no root span; rendering by parent-child edges only

  checkout.handle            812 ms   span 0e11  parent 7c40
  ├─ pricing.quote            94 ms   span 3a92  parent 0e11
  ├─ inventory.reserve       141 ms   span 51bd  parent 0e11
  │  └─ ledger.hold           88 ms   span 7c40  parent 51bd
  │     └─ checkout.handle   812 ms   span 0e11  parent 7c40   [seen]
  ├─ payment.authorize       402 ms   span c118  parent 0e11
  └─ notify.enqueue            9 ms   span 22f5  parent 0e11

  19 spans, 18 edges, 0 roots, 1 cycle
  wall clock span:  41.6 s
  sum of durations: 1.454 s

graph TD
  A["checkout.handle<br/>span 0e11 · 812 ms"] --> B["pricing.quote<br/>span 3a92 · 94 ms"]
  A --> C["inventory.reserve<br/>span 51bd · 141 ms"]
  A --> D["payment.authorize<br/>span c118 · 402 ms"]
  A --> E["notify.enqueue<br/>span 22f5 · 9 ms"]
  C --> F["ledger.hold<br/>span 7c40 · 88 ms"]
  F --> A
  B --> G["cache.get<br/>span 9d04 · 2 ms"]
  D --> H["risk.score<br/>span b761 · 388 ms"]
  H --> I["risk.model.v3<br/>span 4e0c · 371 ms"]
  I --> J["feature.fetch<br/>span 6a55 · 18 ms"]
  J --> H

checkout.handle is its own great-grandparent. risk.score is its own grandparent. Neither service calls the other one; ledger has no client for checkout, and feature-fetch has no client at all, it is a library.

What we checked

• Clock skew. All hosts in the trace are within 0.4 ms of the same NTP source. The 41.6 s wall clock is not skew; it is the distance between the earliest span start and the latest span end, and the durations do not fill it. There are 40.1 seconds inside this trace during which no span is open.
• ID collision. A parent id colliding with a real span id would do this. The ids are 64-bit and the collector holds 4.1 billion spans, which puts the birthday probability for a single collision at about one in a billion, and this trace contains two. Both collisions are between spans in the same trace.
• The producing library. Version pinned across all six services, no local patches, checksums match upstream.
• Replay. We replayed the exact request against staging 4,000 times. Every trace has a root.

The order the spans arrived

The collector timestamps each span on receipt, independently of the span's own clock. Span 0e11 — the one with no parent in the trace and a parent id of 7c40 — was received at 04:41:19.882. Span 7c40 was received at 04:41:21.114.

A span's parent id is written by the parent, into the header it passes down, and then by the child, into the span it emits. 0e11 was emitted with a parent id that 7c40 had not generated yet.

Status

The trace has been kept. It is excluded from the p99 aggregation by a filter on its trace id, which is a filter with exactly one entry in it, and I would like it noted that this was the correct thing to do and not a fix.

Compare stories/nightly-0300, where the completion also precedes the start.