Tracing LLM Calls

A user asks your support assistant a question and gets a confident, wrong answer. The ticket lands on your desk with no stack trace, no logs, and no way to know which prompt version ran, which documents were retrieved, or how long the model took. This is the debugging void that LLM tracing exists to fill.

A trace is a tree of spans. Each span is one unit of work with a name, a start time, a duration, and a set of attributes. The root span covers the whole user request; child spans cover each stage inside it.

user request (root span, 1840ms)
├── prompt assembly (12ms)         ← system prompt v14 + history + retrieved docs
├── retrieval (640ms)              ← vector search over 3 chunks
│   └── rerank (210ms)              ← cross-encoder rescoring
├── model call (1150ms)             ← claude-sonnet-4-6, 1420 in / 380 out tokens
└── post-processing (38ms)          ← citation validation, PII redaction

Read the waterfall top to bottom and the story is already visible: retrieval and reranking ate 850ms of the 1840ms total. Without spans, you would have optimized the model call — the wrong target.

Every span should carry the same core attributes so any stage can be compared against any other:

Notice what is missing: the full user message and full model output. Those are large, often sensitive, and belong in a separate payload store linked by ID — not jammed into span attributes where they bloat every query. Traces answer what happened and where; payloads answer exactly what was said.

The naive way to add tracing is to sprinkle print() calls around your LLM client. It works until the second service, the second model, or the second concurrent request — then the output is an interleaved mess with no shared identity. Structured tracing fixes this by giving every operation a span with a shared trace ID.

import time, uuid, json

class Span:
    def __init__(self, name, trace_id, parent_id=None):
        self.name = name
        self.trace_id = trace_id          # shared across the whole request
        self.span_id = uuid.uuid4().hex[:8]
        self.parent_id = parent_id        # links child to parent
        self.start = time.perf_counter()
        self.attributes = {}

    def set(self, key, value):
        self.attributes[key] = value

    def finish(self):
        return {
            'name': self.name,
            'trace_id': self.trace_id,
            'span_id': self.span_id,
            'parent_id': self.parent_id,
            'duration_ms': round((time.perf_counter() - self.start) * 1000, 1),
            'attributes': self.attributes,
        }

class Tracer:
    def __init__(self):
        self.spans = []

    def span(self, name, parent=None):
        trace_id = parent.trace_id if parent else uuid.uuid4().hex[:16]
        s = Span(name, trace_id, parent.span_id if parent else None)
        self.spans.append(s)
        return s

The non-obvious line is trace_id = parent.trace_id if parent else .... A child span must inherit the parent's trace ID, not generate a new one — otherwise every stage becomes an isolated trace and the waterfall collapses. The parent_id is what rebuilds the tree.

Instrument a real call:

tracer = Tracer()
root = tracer.span('chat_request')
root.set('prompt_version', 'support-v14')
root.set('model', 'claude-sonnet-4-6')

retrieval = tracer.span('retrieval', parent=root)
retrieval.set('retrieved_passages', ['doc-102', 'doc-87', 'doc-41'])
time.sleep(0.05)  # simulated vector search
retrieval.finish()

model = tracer.span('model_call', parent=root)
model.set('input_tokens', 1420)
model.set('output_tokens', 380)
time.sleep(0.11)  # simulated generation
model.finish()

root.finish()
print(json.dumps(tracer.spans, indent=2))

Output (trimmed):

[
  {"name": "retrieval", "trace_id": "9f2c...", "parent_id": "a1b2...", "duration_ms": 50.2, "attributes": {"retrieved_passages": ["doc-102", "doc-87", "doc-41"]}},
  {"name": "model_call", "trace_id": "9f2c...", "parent_id": "a1b2...", "duration_ms": 110.4, "attributes": {"input_tokens": 1420, "output_tokens": 380}},
  {"name": "chat_request", "trace_id": "9f2c...", "parent_id": null, "duration_ms": 160.8, "attributes": {"prompt_version": "support-v14", "model": "claude-sonnet-4-6"}}
]

Every span shares trace_id 9f2c..., so a collector can rebuild the full request from any service that emitted a piece of it. In production you would export these spans to OpenTelemetry rather than printing them — the span model is identical, only the exporter changes.

Your chat service calls a retrieval service, which calls an embedding service, which calls the model provider. Each is a separate process, often a separate deploy. If each generates its own trace ID, you get four unrelated traces and no way to answer 'what happened to user 42's request?'

Context propagation solves this by passing the trace identity through the call. The caller injects its trace ID and span ID into the outgoing request; the callee extracts them and uses them as its own trace ID and parent span ID.

TRACE_ID_HEADER = 'x-trace-id'
SPAN_ID_HEADER = 'x-span-id'

def inject(headers, span):
    headers[TRACE_ID_HEADER] = span.trace_id
    headers[SPAN_ID_HEADER] = span.span_id
    return headers

def extract(headers, tracer, name):
    trace_id = headers.get(TRACE_ID_HEADER)
    parent_id = headers.get(SPAN_ID_HEADER)
    if not trace_id:
        return tracer.span(name)  # no context: start a fresh trace
    parent = SimpleNamespace(trace_id=trace_id, span_id=parent_id)
    return tracer.span(name, parent=parent)

The retrieval service receives the request, calls extract, and its spans automatically join the caller's trace. The embedding service does the same one hop further. The result is one waterfall across three services.

Two failure modes to design for:

• Header loss through queues. If a request passes through a message queue, headers do not travel with the message body. Inject the trace ID into the message envelope instead, and extract it on the consumer.
• Clock skew. Span start times come from different machines. Never compute parent-child duration from timestamps across services — use the parent-child relationship, not wall-clock subtraction.

Propagation is also what makes incident replay possible: with a trace ID from a customer ticket, you can pull every span across every service and reconstruct the exact request.

Full-fidelity tracing on every request is the right default for a debug session and the wrong default for production. At 50,000 requests per day with ten spans each, you are storing half a million spans daily — and most of them are boring, successful, identical requests.

Sampling decides which traces to keep. The two strategies answer different questions:

Head-based sampling is a coin flip at the root: if the root span is sampled, every child is sampled with it, so the trace stays whole. Tail-based sampling waits until the request finishes, then keeps the trace only if it errored or exceeded a latency threshold. Tail-based catches the traces you actually debug, but it requires buffering every span in memory until the decision — a real cost at high traffic.

A practical middle ground: sample 100% of requests that error or exceed your latency budget, and 1% of healthy requests. You keep full visibility into failures and a statistical sample of normal behavior.

What you record matters as much as what you keep. Record retrieved passages and tool arguments in spans — they are the difference between 'the model answered wrong' and 'the model answered wrong because it was given the wrong document.' But redact PII before it reaches a span attribute. A trace that leaks customer emails into your observability backend is a data exposure incident, not a debugging tool.

Storage cost is the reason this topic sits next to metering token usage: traces and token usage are the two production signals you cannot debug without, and both need sampling and retention policies to stay affordable.