Skip to content

10 min read

Timings say where the request went, never why the answer changed

On this page

By 02:40 the on-call engineer has two trace IDs in front of her: one from a contract-summary request that scored 84 on Monday afternoon, one from the same fixture case scoring 51 on Tuesday morning. The service is instrumented properly. Each request carries a correlation ID — one identifier stamped on it at the edge and passed to every service it touches, so the records can be stitched back together — and each trace has four spans — retrieval, rerank, generation, postprocess — with start times, durations, status codes and the tenant ID as an attribute. She puts them side by side.

text
trace 4c1f… (Mon 14:22, score 84)      trace 9a07… (Tue 02:31, score 51)
  retrieval    182 ms  OK                retrieval    174 ms  OK
  rerank        61 ms  OK                rerank        58 ms  OK
  generation  1,604 ms  OK               generation  1,588 ms  OK
  postprocess   39 ms  OK                postprocess   41 ms  OK
  total       1,886 ms  200              total       1,861 ms  200

There is nothing here. The two traces agree to within 3% on every duration, both return 200, both carry the same tenant and the same route. Twenty minutes of comparing traces produces the observation that the bad request was slightly faster than the good one, which is true and useless. This is the normal outcome, because the fields recorded are the fields that stay the same whenever the system is functioning at all. Spans built this way answer "where did the time go, and did anything throw?" — questions the team answered in the first three minutes of the incident by looking at the latency and error dashboards from chapter 1.

Attribution needs the content of each stage, not its shape

Chapter 1 of topic 15.2 made the case for what belongs on the model-call span itself: the resolved model identifier as opposed to the alias you requested, the effort and thinking configuration, the rendered prompt and the completion, the stop reason, the token counts kept separate. Assume all of that is in place here. It closes the gap for one class of regression and leaves another wide open, because in a retrieval-augmented system — one that searches an index for passages relevant to the question and pastes them into the prompt before the model answers — the model call is the last link in a chain, and most of what varies between a good answer and a bad one entered the request before the model ever saw it.

The chain has four points where content can change without any timing or status code moving:

  • What was retrieved. Which document chunks came back, in which order, with which similarity scores, from which index build, produced by which embedding model — the model that turns a passage into the numeric vector the index is searched by — and which chunking configuration, meaning the rules that cut a document into those passages in the first place.
  • What the template rendered into. Which prompt version, which template ID, and the actual values interpolated — the retrieved chunks, the conversation history, the tenant's custom instruction block, the account record a previous step looked up.
  • Which configuration resolved. Whether a per-tenant override, an environment variable, or a feature flag rewrote the routing, the model, the retrieval depth or the post-processing rules for this specific request.
  • What came back and what you did to it. The raw completion, plus whatever the post-processing step changed: truncation, JSON repair, a regex that strips a preamble, a fallback that substitutes a template when parsing fails.

Recorded, the retrieval span for the Tuesday request looks like this:

json
{
  "name": "retrieval",
  "trace_id": "9a07f31b8c2d4e50",
  "duration_ms": 174,
  "status": "OK",
  "attributes": {
    "retrieval.index_name": "contracts-v3",
    "retrieval.index_build_id": "bld_20260616_2141",
    "retrieval.embedding_model": "text-embed-3-lg",
    "retrieval.chunker_version": "5.2.0",
    "retrieval.top_k": 5,
    "retrieval.query_hash": "sha256:71c0a4…",
    "retrieval.results": [
      {"doc_id": "ct_88213#p14", "score": 0.811, "tokens": 512},
      {"doc_id": "ct_88213#p15", "score": 0.804, "tokens": 498},
      {"doc_id": "ct_88213#p02", "score": 0.799, "tokens": 511},
      {"doc_id": "ct_91007#p07", "score": 0.788, "tokens": 505},
      {"doc_id": "ct_88213#p31", "score": 0.771, "tokens": 486}
    ]
  }
}

Nothing in that block is expensive to produce — every value is already in memory when the span closes. The Monday trace, once the same attributes are added and both runs are replayed, returns bld_20260609_0330, text-embed-3-md, chunker 5.1.4, and a different fourth and fifth result. Two identical-looking traces turn out to have been answering from different evidence.

Configuration provenance is the attribute teams add last and wish they had added first. This service resolves its behaviour from four layers — a checked-in default, an environment variable, a per-tenant override row, and a feature flag with a percentage rollout — so the value in the code you are reading at 03:00 is a claim about what should have happened rather than a record of what did. Recording config.resolved_from next to each resolved value costs one short string per attribute and answers a question that otherwise takes an hour: at 03:30 the team found that top_k, the number of retrieved chunks handed to the prompt, was 5 for most tenants and 8 for the four tenants enrolled in a retrieval experiment, which was in nobody's mental model of the system and appeared in no repository.

The post-processing span deserves the same treatment, because it is where a defect can be created after the model has done nothing wrong. This service applies three transforms in order — a JSON repair pass for completions that fail to parse, a truncation of the obligations array to twenty entries, and a fallback that substitutes an empty summary object when repair fails — and each is a silent rewrite unless it is recorded. postprocess.repair_applied: true on 31% of Tuesday's requests against 2% of Monday's would have been the most informative number available at 02:40, and it costs one boolean.

Slices only help if production requests carry them

The eval job from chapter 1 reports per slice, so the alert names contract_summary. That is a label the eval harness assigns to its own fixtures. Unless production requests carry the same label, there is no way to ask "show me the production traffic for the slice that regressed", and the investigation immediately widens to all 30,000 daily requests. Classifying the request into its slice at the edge and stamping eval.slice onto the root span costs one dictionary lookup and makes the two systems joinable:

There is a second reason to make the eval harness call the production entry point rather than its own copy of the client. A harness that assembles its own requests measures a system that resembles yours: every override, middleware and flag that production applies is absent, and the score can stay green while users are served something else entirely. Sending eval traffic through the same door, tagged with an eval.run_id and a synthetic tenant, means each fixture case produces an ordinary trace carrying every attribute above — so the run that scored 60.2 is itself sixty traces you can open, which is how the fixture case and the production request at the top of this chapter came to be comparable at all.

sql
-- Which retrieval configuration served the regressed slice, before and after?
SELECT
  date_trunc('hour', ts)                    AS hour,
  attributes->>'retrieval.index_build_id'   AS build,
  attributes->>'retrieval.embedding_model'  AS embed_model,
  attributes->>'prompt.template_version'    AS prompt_v,
  attributes->>'gen_ai.response.model'      AS model,
  count(*)                                  AS requests
FROM spans
WHERE name = 'retrieval'
  AND attributes->>'eval.slice' = 'contract_summary'
  AND ts BETWEEN now() - interval '36 hours' AND now()
GROUP BY 1, 2, 3, 4, 5
ORDER BY 1;

Run at 02:52, that query returns something the trace comparison could not. Until 21:40 on Monday, every contract-summary request used build bld_20260609_0330 with text-embed-3-md and prompt version 4.2. From 21:41 onward, 100% of them use bld_20260616_2141 with text-embed-3-lg and prompt version 4.3, and the resolved model identifier changes at the same minute from claude-opus-5 to a pinned earlier snapshot. Four attributes changed simultaneously, at a time when no deploy went out, which is its own interesting fact.

That is attribution reaching its useful limit. The telemetry has narrowed "something got worse" to "these four inputs changed at 21:41", and it will not narrow further, because everything downstream of that minute ran on all four changes at once. Distinguishing which of them carries the regression is a different activity from tracing, and chapter 3 is about why the obvious way to do it does not work.

What recording all of this costs

The volume is smaller than people expect. For this system, a fully populated trace carries roughly 9 KB of rendered prompt, 2 KB of completion, 1.5 KB of retrieval metadata and 0.5 KB of everything else, or about 13 KB before compression and 3–4 KB after. At 30,000 requests a day that is about 110 MB a day, 10 GB for a 90-day window — an object-storage line item somewhere under $1 a month, plus whatever your index costs. Storage is not the constraint that stops teams from doing this.

The constraint is what the payload contains. The rendered prompt for a contract summariser is customer contract text: named counterparties, pricing, and in some tenants personal data of signatories. Writing that into a general-purpose observability platform means a second copy of your most sensitive corpus in a system with different access controls, a different retention policy, a different jurisdiction, and a much longer list of people who can query it. Several of your enterprise contracts will have language about where that data may live and how long you may keep it, which turns a monitoring decision into a contractual one.

FieldWhy an incident needs itSensitivityPractical policy
Retrieval doc IDs and scoresShows the evidence changedLow — identifiers onlyAlways, full retention
Index build ID, embedding model, chunker versionNames the retrieval configurationNoneAlways, full retention
Prompt template ID and versionNames the instruction setNoneAlways, full retention
Resolved model, effort, max tokensNames what answeredNoneAlways, full retention
Rendered prompt (full text)The only way to see what the model actually readHigh — customer contentSampled, short retention, redacted, tenant-gated
Completion (full text)The only way to see what went wrongHighSame as rendered prompt
Output hash and lengthDetects change without storing contentNoneAlways, full retention

The pattern in the right-hand column is a split between identifiers, which are cheap and safe and belong on every request forever, and content, which is expensive in every sense and belongs under a policy. Storing a content hash alongside every prompt and completion gives you a surprising amount of the benefit at none of the cost: you can prove that two runs of the same fixture produced different outputs, and that the rendered prompt differed, without keeping either. Storing document IDs rather than document text gives you the same leverage on the retrieval side, provided you can still fetch the document — which is exactly what an index rebuild can take away from you, so keep the chunk text keyed by build ID, or accept that traces older than the last rebuild are partly unresolvable.

Access is the other half of the policy. If the payload store is queryable by anyone with an observability login, you have widened the set of people who can read customer contracts from a handful of support engineers to the entire company, and no amount of retention tuning compensates for that. Keep content in a separate index with its own access group, log the queries against it, and make the identifier-only view — which answers most incident questions — the one that is open by default.

Sampling decides which incidents you can investigate

If content capture is sampled, the sampling rate is a bet about which requests you will want to look at later, and a uniform 5% is the worst bet available. The requests you will want are the ones that went wrong, and a uniform sample gives you a 5% chance of holding any specific one. The customer who escalates a bad summary will quote a request ID, and you will discover it was not sampled.

Bias the policy toward the requests that are already suspicious:

yaml
capture:
  default_rate: 0.01           # baseline, keeps the corpus representative
  rules:
    - when: "eval.slice in ['contract_summary', 'redline']"
      rate: 1.0                # slices with automated downstream consumers
    - when: "gen_ai.response.finish_reason in ['refusal', 'max_tokens']"
      rate: 1.0
    - when: "postprocess.repair_applied == true"
      rate: 1.0
    - when: "feedback.rating == 'negative'"
      rate: 1.0                # applied retroactively within the buffer window
  retention:
    identifiers_days: 365
    content_days: 14
    content_redaction: ["email", "phone", "iban", "national_id"]
  tenant_overrides:
    zero_retention_tenants: { content_days: 0 }

The retroactive rule is the one that pays for itself. Hold the last thirty minutes of full payloads in a buffer, and when a negative rating or a failed validation arrives for a request ID, promote that request's payload out of the buffer into durable storage. You end up keeping the interesting 0.5% rather than a random 5%, at a tenth of the volume.

Tracing is not evaluation, and complete telemetry is not a cause

Two confusions are worth heading off. The first is that a well-instrumented request path measures quality; it does not, and a system with perfect semantic traces and no scored fixture set still learns about regressions from customers. Traces explain a drop that something else detected. The second is that a complete trace identifies a cause. What the query above produced is a list of things that differ between the good window and the bad one, and difference is not causation — four attributes moved together, and at most some of them matter.

One property of this domain makes stored payloads worth more than they look. In an ordinary service a trace that records the inputs is nearly as good as one that records the output, because you can replay the inputs and get the same result. Here, replaying an identical prompt against an identical configuration produces a different completion, so an output you did not store is genuinely gone and "reproduce it locally" is a wish rather than a plan. The stored completion for the request a customer complained about is the only evidence that request will ever have, which is why the retroactive promotion rule matters more than the sampling rate.

The team now has the two comparable requests it lacked at 02:40, and they differ in four ways at once. The obvious next move is to put the changes back one at a time until the score recovers. The next chapter is about what happens when that is attempted at 03:10 under pressure, and why the intermediate states it walks through were never valid configurations in the first place.

Incident response for AI systems — read the current version at https://daviddominguez.dev/learn/en/incident-response-for-ai-systems/timings-say-where-the-request-went-never-why-the-answer-changed

Back to top