Splitting 45 seconds into provider, retry and tool time

The support ticket says the reply took about a minute and then stopped in the middle of a sentence. It quotes the last thing the agent said — "You can request a replacement label from the Shipments tab, then" — and it carries a request id, because the product puts one in the footer of every answer for exactly this reason. Searching the access log for that id returns one line:

2026-03-24T09:14:52.118Z acme POST /v1/answer 200 45.2s 3.1kB req=8f10c2a4

Two engineers read that line and disagreed about what it meant. One said the provider was having a slow morning and the answer got cut off by a client timeout. The other said the answer looked truncated because the model hit its token ceiling, which has nothing to do with the 45 seconds. Both stories are consistent with the line, and the line is the entire external record of the incident.

What a request record establishes, and where it stops#

The log line is not useless. It fixes the incident in time to the millisecond, names the tenant, confirms the route, and settles that the service returned 200 with a 3.1 kB body — so the response was produced and delivered rather than dropped, and the truncation happened before the bytes left the process rather than in transit. It also gives you the request id that joins to everything else. That is a real set of facts and it is the set of facts a request record is built to carry: one row per request, describing the request's boundary.

What it cannot carry is structure, because there is one row and the request had parts. Every question the disagreement turns on is a question about a part. The trace for the same request:

POST /v1/answer                              a1   45.20s   200   req=8f10c2a4
└─ agent.run support_agent                   b1   45.00s   steps 2
   ├─ agent.step 1                           c1    4.30s
   │  ├─ chat claude-opus-5                   c2    3.70s   in 6,240   out 188   tool_use
   │  └─ execute_tool lookup_order            c3    0.60s   ok
   └─ agent.step 2                           d1   40.60s
      ├─ chat claude-opus-5                   d2   15.00s   ERROR  APITimeoutError  attempt 1
      ├─ chat claude-opus-5                   d3   15.00s   ERROR  APITimeoutError  attempt 2
      └─ chat claude-opus-5                   d4   10.50s   ok  in 11,900  out 8,192  max_tokens

Both engineers were partly right and the combination is the actual bug. Attempt three finished in 10.5 seconds and returned finish_reason: max_tokens with exactly 8,192 output tokens, so the answer was truncated by the output ceiling. The 45 seconds came from somewhere else entirely: two attempts that each ran for exactly 15.00 seconds and then failed identically.

Exactly 15.00, twice, is the signature of a client-side timeout rather than anything happening upstream, and 45.2 total is the second half of the same signature. Someone had set timeout=15 on the Anthropic client three months earlier, in a change whose description said "fail fast instead of hanging for ten minutes". The SDK's max_retries defaults to 2, and timeouts are retryable, so the worst-case wall clock for that configuration is timeout × (max_retries + 1) — 45 seconds. The setting intended to cap latency at 15 seconds tripled it.

Why the call needed more than 15 seconds is the last piece, and it is the same piece as the truncation. This tenant's route runs at effort: "xhigh" with thinking on and max_tokens: 8192. On the current models max_tokens bounds thinking and response text together, so a request at high effort spends a large share of the ceiling before it emits a visible token; at that effort and that ceiling the call routinely lands between 12 and 18 seconds, sits astride the timeout, and when it does complete it has spent the whole budget and stops on max_tokens. One misconfigured pair of numbers produces both symptoms, and neither symptom is visible in the log line.

Splitting the total this way is what turns the incident into a decision. Thirty of the forty-five seconds bought nothing, which points at the timeout and retry configuration rather than at the provider, the retrieval layer, or the model choice — and each of those three would have been a plausible place to spend a week if the only evidence had been "it took 45 seconds".

The keep-or-drop decision was made before anything happened#

There is a version of this chapter where the trace does not exist, and it is the common version. Traces on this service are head-sampled at 5%: the sampling decision is taken when the root span is created, from a hash of the trace id, and it propagates to every child so that a trace is kept or dropped whole. A request that turns out at second 45 to be the most interesting request of the week had its fate settled at millisecond zero, when it was indistinguishable from the other 41,999 requests that day.

The reflex is to turn sampling to 100% and argue that storage is cheap. For span count alone that argument holds: 42,000 requests a day at roughly 21 spans each is under a million spans, which nobody's bill notices. It stops holding once the spans carry content. Prompt capture on this workload averages 9 kB per model call across five calls a request, so full capture is about 1.9 GB of trace payload a day; at the $2.50 per ingested gigabyte the team was quoted, with thirty-day retention, that is roughly $4,300 a month against about $220 at 5%. Affordable for a quarter, which is exactly how long it survives — until the first budget review, or the first privacy review, at which point the rate reverts to whatever number is defended most loudly in the meeting rather than to a policy about which requests are worth keeping.

The deeper problem with raising the rate is that it does not answer the question that was asked. Head sampling is uniform by construction; it cannot prefer interesting traces, because at the moment it decides, no trace is yet interesting. Buying more of a uniform sample is a way of paying for coverage of the boring majority in the hope of incidentally catching the rare case.

Deciding at the end, and the window that eats your longest traces#

Tail sampling inverts the order: the collector — the intermediate service your applications export spans to before anything reaches a storage backend, where batching, filtering and sampling rules are applied outside your application's process — buffers spans by trace id, waits until the trace looks finished, evaluates policies against the completed trace, and only then keeps or drops it. That makes "keep the traces that are worth keeping" expressible, because by decision time the properties you care about are present.

processors:
  tail_sampling:
    decision_wait: 120s          # must exceed p99.9 run duration, not p95
    num_traces: 200000
    expected_new_traces_per_sec: 60
    policies:
      - name: errors
        type: status_code
        status_code: {status_codes: [ERROR]}
      - name: slow-runs
        type: latency
        latency: {threshold_ms: 20000}
      - name: truncated-answers
        type: string_attribute
        string_attribute:
          key: gen_ai.response.finish_reason
          values: [max_tokens, refusal]
      - name: retried
        type: numeric_attribute
        numeric_attribute: {key: llm.attempt, min_value: 2, max_value: 100}
      - name: baseline
        type: probabilistic
        probabilistic: {sampling_percentage: 2}

decision_wait is the setting that quietly defeats this, and its default is 30 seconds. The timer starts when the collector sees the first span of a trace, and when it expires the trace is evaluated with whatever has arrived and the decision is cached; spans that arrive afterwards are matched against the cached decision or dropped. A 45-second run under a 30-second window is evaluated at second 30, when the retry attempts have not yet ended and the latency policy sees a trace that is 30 seconds long with an unfinished step — sometimes kept, sometimes not, and either way missing its tail. The traces that exceed the window are the slow ones, which is to say the ones every policy in that config was written to catch. Set the window from the p99.9 of your run duration rather than the p95, and size num_traces for concurrency times window: at a peak of 6 requests a second and a 120-second window, roughly 720 traces are in flight, which is nothing in memory and worth computing anyway.

The operational cost that is easy to miss is that tail sampling requires every span of a trace to reach the same collector instance. A fleet behind a normal round-robin load balancer gives each collector a partial trace, and each one then samples its fragment on incomplete information. The fix is a trace-id-aware layer in front — the collector's own load-balancing exporter, routing by trace id — which turns a stateless component into a stateful, shard-aware one. That is a real piece of infrastructure to own, and it is the honest price of deciding at the end instead of the beginning.

Whether the symptom had been a 500 changes the urgency more than the design. Every reasonable policy keeps errors, and most teams already carry an error override even under head sampling, so a 500 would probably have had its trace waiting. The gap this incident sits in is the successful-looking request: status 200, no exception, a response body delivered, and a user who got a broken answer. Making slowness and finish_reason into keep signals is what closes it, and that is a decision about what counts as a failure rather than a decision about sampling rate.

What the trace still does not settle#

The tree says two attempts hit a 15-second client timeout. It does not say why the provider needed more than 15 seconds on those attempts, because your span ends at your socket. Whether the model was queued, whether the account was near a rate limit, whether that region was degraded — none of that is in your data, and the route to it is the response id and the provider's own status and usage reporting. A trace bounds the question to "the time was spent upstream" and hands it over.

It also describes one request. That this configuration produces a 45-second worst case is a fact about the configuration, but how often it fires, whether it is concentrated on one tenant, and whether the fix moved anything are questions about a population, and answering them from stored traces means answering them from a sample that was deliberately biased towards the interesting ones. Those belong to metrics, which is a later topic.

The narrower limit is that everything in this chapter worked because something went visibly wrong: a status, a timeout, a finish reason. The next chapter is a trace in which every span is OK, every duration is unremarkable, nothing timed out, nothing was retried, and the user was told the agent could not help them.