Per-stage spans turn a slow answer into a named stage

An assistant that answers questions out of an organisation's own documents does its work in steps. It turns the question into a vector, searches a prepared store of passages for the closest ones, renders those passages into a prompt, and calls a language model to write the answer. A request that took seven seconds spent those seven seconds distributed somehow across those steps, and when the only figure the service records is the total, nothing in the record says which distribution it was.

Two pieces of vocabulary make the repair describable, and both are borrowed from distributed tracing rather than invented for retrieval. A span is a timed record of one unit of work, carrying a start, a duration and a bag of key-value attributes. A trace is the set of spans sharing an identifier because they belong to the same request. Two more come from statistics, and they describe different parts of one distribution rather than two distributions: p50 is the duration half of requests finish inside, and p95 the duration all but one request in twenty finish inside, so p95 is a statement about the slowest sliver of traffic rather than about the typical request.

Why a total cannot be attributed to a stage#

The reason a total resists attribution is arithmetic rather than tooling. Write the wall-clock duration of a request as the sum of the durations of the stages it passed through, plus whatever time it spent between them — waiting for a worker, holding a connection, serialising a response. That is one equation. Its unknowns are the stage durations, and there are as many of them as there are stages. One equation in that many unknowns has an infinity of solutions, and every candidate explanation of a regression is one of those solutions.

Instrumenting stages does not add equations so much as it removes unknowns. Every stage that emits its own duration moves a term from the unknown side of that equation to the known side. Instrument all of them and exactly one unknown survives: the total, minus the sum of the spans. That leftover is not error and it is not noise. It is the time the request spent in code that no span covered, and it has a short list of candidates — queueing for a worker, waiting on a connection pool, serialising the response — every one of which is a real thing that can be fixed.

An analogy is available here as long as its limit travels with it. A total duration is a bill with one line on it, and a trace is the itemised version; you cannot dispute a total and you can dispute a line. Where the comparison breaks is the part that matters: an itemised bill's lines sum to its total by construction, because the total was computed from the lines, whereas stage spans are measured independently of the total and need not sum to it. The analogy understates the problem in that spot, because a missing line on a bill is a discrepancy anybody can query, while time spent outside every span leaves no line at all until somebody performs the subtraction.

The pair of percentiles carries a second piece of information, and it lives in the gap between how far each of them moved rather than in where either of them sits. A change that makes code slower makes it slower for every request, so it shifts the whole distribution and p50 and p95 rise together. A change that moves p95 and leaves p50 where it was cannot be that. It means most requests are unaffected and a minority now do substantially more work, which usually means an input got bigger for that minority rather than the code getting slower for everyone. Knowing that narrows the search to "which stage's input grew, and for which requests", and neither half of that question can be answered from a single duration.

Two things get argued about as one here, and separating them is worth a sentence each. The requirement is that every slow answer be attributable to a stage and every user complaint be openable as a record. Emitting one span per stage on a shared trace id, with counts carried as attributes, is a design decision that meets that requirement; timing each stage into a structured log line keyed by request id would meet it too. What cannot meet it is a single duration, however carefully it is percentiled, because no arrangement of one number recovers the terms that were summed to produce it.

One trace id, one span per stage, attributes that count things#

The instrumentation that resolves this is small, and it uses the vocabulary distributed tracing already has. Every request gets a trace id; every stage opens a child span under it; every span carries attributes describing not just how long it took but how much it handled. The second part is what separates a useful trace from a decorative one, because a span that says retrieve: 41ms tells you nothing about whether 41 ms was for five chunks or fifty.

from opentelemetry import trace

tracer = trace.get_tracer("rag")


def answer(question: str, principal: Principal, k: int = 5) -> Answer:
    with tracer.start_as_current_span("rag.answer") as root:
        root.set_attribute("rag.question_chars", len(question))
        root.set_attribute("rag.principal_groups", len(principal.grants))

        with tracer.start_as_current_span("rag.embed_query") as s:
            qvec, cached = embed_query_cached(question)
            s.set_attribute("rag.embed.model", EMBED_MODEL)
            s.set_attribute("rag.embed.cache_hit", cached)

        with tracer.start_as_current_span("rag.retrieve") as s:
            hits = retrieve(qvec, principal, k=k)
            s.set_attribute("rag.retrieve.k_requested", k)
            s.set_attribute("rag.retrieve.k_returned", len(hits))
            s.set_attribute("rag.retrieve.top_score", hits[0].score if hits else 0.0)
            s.set_attribute("rag.retrieve.chars_returned", sum(len(h.payload["text"]) for h in hits))
            s.set_attribute("rag.retrieve.filtered", True)

        with tracer.start_as_current_span("rag.augment") as s:
            prompt = build_prompt(question, hits)
            s.set_attribute("rag.prompt.tokens", count_tokens(prompt))
            s.set_attribute("rag.prompt.chunks_rendered", len(hits))
            s.set_attribute("rag.prompt.truncated", was_truncated())

        with tracer.start_as_current_span("rag.generate") as s:
            resp = client.chat.completions.create(...)
            s.set_attribute("rag.gen.model", GEN_MODEL)
            s.set_attribute("rag.gen.input_tokens", resp.usage.prompt_tokens)
            s.set_attribute("rag.gen.output_tokens", resp.usage.completion_tokens)
            s.set_attribute("rag.gen.cached_input_tokens", resp.usage.prompt_tokens_details.cached_tokens)
            s.set_attribute("rag.gen.finish_reason", resp.choices[0].finish_reason)

        root.set_attribute("rag.trace_id", format(root.get_span_context().trace_id, "032x"))
        return Answer(..., trace_id=format(root.get_span_context().trace_id, "032x"))

Look at what those attributes count rather than time, because the choice is deliberate. A duration on its own is a level, and a level means nothing until there is a second reading to set beside it. A duration paired with a count is a rate, and a rate is comparable across requests of different sizes. k_requested and k_returned are such a pair, so a reader sees a gap rather than a value; chars_returned measures how big the retrieved text was, which can move while the number of chunks stays fixed.

Returning the trace id in the answer object matters as much as emitting it. A support ticket that says "this answer was wrong" is unactionable; a ticket carrying trace_id=4f2a... is a lookup. Surfacing it in the UI as a small identifier next to the answer, or logging it against the conversation record, costs one field and converts every user complaint into an artefact that can be opened.

Opening a single slow trace from an affected population settles the question in one look.

rag.answer                                       7,412 ms
├─ rag.embed_query          cache_hit=false         38 ms
├─ rag.retrieve             k_returned=5           44 ms
│                           chars_returned=39,910
├─ rag.augment              tokens=11,206           7 ms
│                           chunks_rendered=5  truncated=false
└─ rag.generate             input_tokens=11,206  7,309 ms
                            output_tokens=284    cached_input_tokens=0

Read the children against the root before reading any of them on their own. The four child spans come to a little less than the root's total, and the shortfall — some fourteen milliseconds — is the residual from the arithmetic above: time this request spent inside the handler and outside every span, in the code between the with blocks and at the entry and exit of the function. That the shortfall is small is the useful part. It says these four spans between them account for essentially all of the root's total, so whatever is to blame is one of the four and not something the instrumentation cannot see. Had the shortfall been seconds rather than milliseconds, the four spans would all have looked innocent and the answer would still have been in the trace.

Two of the attributes are the same quantity measured twice by parties that do not consult each other. tokens=11,206 on the augment span is counted locally, by whatever tokeniser this service runs over the prompt it has just built. input_tokens=11,206 on the generate span is read off the provider's response and is the provider's own count of what it received. They are identical, and that agreement licenses two conclusions at once: the tokeniser configured locally is the one the provider is using, and nothing was inserted into or removed from the prompt between rendering it and sending it. When those two figures diverge, the gap is the thing to chase — a system message the client library appends, a tool schema counted at one end and not the other, a template applied server-side — and none of that is visible from either figure on its own.

The same closure holds one boundary earlier. k_returned=5 and chunks_rendered=5 are equal and truncated=false, so every chunk retrieval found was rendered into the prompt: none was dropped for budget, and none was collapsed as a duplicate. That is worth confirming rather than assuming, because a chunk that was retrieved and then silently discarded and a chunk that was never retrieved at all look identical in the finished answer and have entirely different fixes.

With the boundaries closed, the levels can be read. The retrieve span returned five chunks in 44 ms, which is normal, and those five chunks contained 39,910 characters, which is not. A median trace from the same hour showed chars_returned=6,180 and tokens=2,431.

Reading those two traces as a gap rather than as two levels is what makes them diagnostic. Between the median trace and this one the chunk count did not move at all — five in both — while the characters behind those five chunks rose more than sixfold and the prompt token count rose with them. A count that holds still while the size behind it multiplies is the signature of a chunking change, because the chunk count is set by k and the chunk size is set by the chunker. Had k been the thing that moved, the count would have moved with the size, and it did not.

The span attributes therefore make a distinction no duration can: the retrieve stage did not get slower, it got bigger, and the stage that got slower was generation, downstream, as a consequence. Without chars_returned and tokens, the trace would have shown generation taking 7.3 seconds and the investigation would have gone to the model provider's status page.

Why generation time answers to input length at all is the link that makes the consequence a consequence. A model reads the entire prompt before it emits the first token of the answer, and reading is work that scales with how much there is to read; only then does it produce output, one token at a time. So a generate span's duration is a cost growing with the input, plus a per-token cost multiplied by the tokens produced. output_tokens=284 is unremarkable, which leaves the input term holding the seven seconds.

One more attribute reads as a product with a zero in it. Prompt caching at the provider saves the fraction of the input served from cache, multiplied by what an input token costs in money and in time. cached_input_tokens=0 sets the first factor to zero, and a product with a zero factor is zero whatever the others are, so none of the eleven thousand input tokens here was discounted however large the prompt was. A large prompt and a cold cache are separate facts, and this trace records both.

Reading the tail as a shape rather than a number#

Once each stage has its own histogram, the pattern of which percentiles moved in which stage is diagnostic on its own, before anyone opens an individual trace.

That table is a set of gaps rather than a set of levels, and reading it any other way gives nothing. No row states how long a stage ought to take. Each row is a pair — what p50 did and what p95 did — and the second column is read off the difference between the two. Where both percentiles moved, every request got slower, and the listed causes all change the cost of doing the same work. Where only p95 moved, most requests were untouched, and the listed causes all change how much work a minority of requests does.

One row has no stage in it at all, and it is the residual from earlier in this chapter arriving as a symptom. A team that has never thought about the leftover term sees the total rise, checks every stage, finds every stage flat, and concludes that the tracing is broken. The tracing is fine and is telling them something specific: the time went where no span reaches. The third column names the usual places, and the size of the leftover is the size of the problem.

The last row of that table is the one that repays instrumenting early. A retry wrapper that silently retries a timed-out call turns one 4-second failure into a 12-second success, and unless the retry count is a span attribute, the request looks like a single slow call.

That figure is arithmetic about a retry policy rather than a measurement, and working it through is what makes the row usable. Three attempts against a four-second timeout — the first two expiring, the third returning — spend twelve seconds of wall clock on one logical call. From outside the wrapper the request shows one call, one success, and a duration no stage's own behaviour explains, which is why the shape is bimodal: succeeding first time and succeeding on the third attempt differ by a multiple rather than by a margin, so the histogram has two humps rather than a long tail.

Cache-hit flags belong on every stage that has a cache, and the flag is more useful than the aggregate hit-rate metric because it is joinable. A hit-rate gauge tells you the rate fell; the per-span flag lets you ask which principals, which question shapes, or which time window the misses came from. The same argument applies to cached_input_tokens on generation: prompt caching at the provider changes both the cost and the latency of a request by a large factor, and a p95 that moves the week you start appending a timestamp to the top of your prompt template is a cache-invalidation story that is invisible without the field.

Errors need the same treatment as timings. A stage that returns an empty result is not an error in the exception-handling sense and is very much an error in the answering sense, so k_returned=0 deserves a counter of its own. On one internal deployment, 3.4% of questions were retrieving zero chunks because the principal's grant set matched nothing in the collection, and the assistant was politely saying it did not know. No exception was ever raised, no error rate moved, and the behaviour was found only because someone plotted k_returned as a distribution rather than a mean.

That deployment is the clearest instance in this chapter of the mistake worth naming, and it is not a slip in anybody's arithmetic. It is a belief that a defence works. The error rate was being trusted to tell a request that retrieved five chunks apart from a request that retrieved none, and it reads the same on both, because neither of them raises. A signal that does not move when the thing it is supposed to detect happens is not a weak signal — it is a constant, and a constant carries no information about anything that varies. The mean of k_returned fails for the same reason in a milder form: averaged over a population where most requests retrieve five and a few retrieve none, it shifts by an amount indistinguishable from ordinary drift, whereas the distribution has a spike at zero that nothing else produces.

The offline half needs counters, not traces#

The five stages that run on a schedule have the same diagnostic problem and a different shape, because a nightly job over 4,200 documents that emits one trace per document produces 4,200 traces that nobody will open. What that half needs is a per-run summary emitted as a single structured record, with the per-document detail available only for the documents that failed.

{
  "run_id": "ingest-2026-06-12T02:00Z",
  "source": "confluence:SUP",
  "docs_listed": 4207,
  "docs_fetched": 4207,
  "docs_parsed_ok": 4198,
  "parse_failures": 9,
  "mean_chars_per_doc": 6412,
  "chunks_written": 51203,
  "chunks_deleted": 118,
  "embed_tokens": 7391204,
  "embed_batches_retried": 3,
  "wall_clock_s": 683
}

Four of those fields close against each other, and the closure is why they are worth writing side by side rather than one at a time. docs_listed and docs_fetched are equal, so their difference is zero and the fetch stage lost nothing: every document the crawler named, it got. docs_parsed_ok and parse_failures sum to exactly docs_listed, with no remainder at all, so every document that was fetched is accounted for as either parsed or failed. Those two closures are worth more than any of the four figures alone, because together they rule out a category the record never names — a document that neither succeeded nor raised and simply stopped being processed somewhere inside parse. If the sum came up short, that category would exist, and the shortfall would be its size.

Half of those fields exist to be compared against yesterday's. A docs_listed that falls by 15% overnight is the truncated crawl the reconciliation guard from the previous chapter refuses to act on, and the record is what tells you which source it was. A mean_chars_per_doc that halves while docs_parsed_ok stays flat is a parser regression producing near-empty text, which succeeds at every stage, embeds cleanly, indexes cleanly, and destroys retrieval quality for the affected documents without raising a single error. A chunks_deleted in the thousands is either a genuine bulk deletion at the source or a bug, and either way it is worth a human looking at it the same morning.

Every one of those three readings is a gap and not a level. There is no correct value for mean_chars_per_doc; there is last night's value, and the fact that this one is half of it. A differencing instrument is worthless on the night it is first written and valuable on the second, which is an argument for writing it before anybody has a question rather than after somebody does.

The one place per-document spans do pay for themselves offline is on failures. Nine parse failures out of 4,207 is a number that gets ignored for months unless the nine document identifiers are recorded somewhere queryable, and those nine are frequently a coherent class — every PDF over 40 pages, every page containing a particular macro — rather than nine unrelated accidents. Emitting a span only for documents that error, with the identifier and the exception type as attributes, costs almost nothing and turns a rounding-error counter into a list somebody can work through.

Instrumentation has a bill of its own#

Tracing every request at full detail is affordable at the volumes most internal assistants run at and is not affordable at all volumes, so the sampling decision is worth making deliberately rather than by accepting a default. Head sampling at 10% is the usual first move and it has the wrong shape for this problem, since the traces worth having are the slow ones and a uniform 10% sample throws away nine in ten of them. Tail sampling — buffer the spans, keep the trace if the root duration exceeds a threshold or any span errored, drop it otherwise — keeps the population that answers questions. A workable policy is to keep everything above 4 seconds, everything with a non-zero error, and 5% of the rest as a baseline for comparison.

The two have different shapes because of when each decides. A head sampler decides before the request runs, so its decision cannot depend on anything the request has not yet done — duration being the leading example — and it therefore keeps slow traces at exactly the rate it keeps every other trace. A tail sampler decides after the root span closes, when the duration exists and can be read. The population worth keeping is defined by a property that comes into being only at the end, which is why the decision has to be taken there.

Attribute cardinality is the second cost, and it bites in metrics rather than in traces. Promoting a span attribute to a metric dimension multiplies the number of time series by that attribute's cardinality, so a per-stage latency histogram broken down by model and cache_hit is four series and the same histogram broken down by principal_id is one series per user. Keep high-cardinality fields as span attributes, where they are searchable and cost storage rather than series, and keep metric dimensions to the handful of low-cardinality fields you would actually alert on.

The word doing the work there is "multiplies". Adding a second dimension does not add its cardinality to the series count, it multiplies the count by it, so two low-cardinality dimensions stay small while one high-cardinality dimension anywhere in the product makes the whole product large whatever the others are. It does so silently: the histogram still renders, and the invoice arrives a month later.

Spans measure work, not truth#

Everything above is about where time and volume went, and none of it says whether the answer was right. A trace showing 44 ms of retrieval returning five chunks at healthy scores, an 11k-token prompt, and a clean generation is exactly what a completely wrong answer looks like, because a confidently wrong answer is not a slow one. Instrumentation of this kind narrows a performance question to a stage in seconds, and applied to a quality question it produces a tidy record of a system doing the wrong thing efficiently.

That is the same failure as the error rate that never moved, arriving where it is easiest to miss. The trace is constant across the thing it is being asked to discriminate: a right answer and a wrong answer produce the same durations, the same counts and the same finish_reason. A green trace is evidence about work performed rather than evidence about truth, and the temptation to read it as the second is strongest when every field in it looks healthy.

There is one place the two overlap, and it is worth keeping in view: the attributes that make timing diagnosable — chunk_ids, ranks, prompt tokens, k_returned — are the same fields a quality investigation needs, which is why the plain path from the previous chapter returned them in the answer object before any tracing existed. Adding them to spans means they are queryable in aggregate rather than only present on the one answer someone thought to keep.

Cost is worth watching. Attaching the full rendered prompt as a span attribute is tempting and, at 11,000 tokens per request, will make your observability bill exceed your inference bill, quite apart from putting retrieved content into a system with different access controls than the index — the disclosure path from the permission chapter reappears here as an observability decision. Keep identifiers, counts and hashes in spans; keep the rendered prompt in a separate archive with its own retention and its own access rules, keyed by the trace id so the join still works.

All of this reduces to one arithmetic fact and one habit. The fact is that a total is a sum, and a sum cannot be taken apart from the outside; each stage that emits its own duration removes one unknown, and whatever is left when they are all subtracted is a measurement of the time nobody instrumented rather than a rounding error. The habit is to make every span carry a count as well as a clock, because a duration alone is a level and a duration beside a count is a rate — and the difference between a stage that got slower and a stage that got bigger is a difference only a rate can show.

What none of this provides is a way to say whether the release made answers better or worse. Latency has a natural unit and quality does not, so comparing two versions of the system requires deciding in advance what counts as a correct answer, on which questions, and how large a difference has to be before it is real. That instrument has to be built before any of its numbers can be trusted, and building it is the next chapter.