Observabilityobservabilitytracingspanslatencycost

Tracing Agents

A trace is a tree of spans — one per LLM call, tool call and state change — that records what the agent saw, decided, spent and how long it took; it is the primary artefact for both debugging and evaluation.

▶ InteractiveInterview question
Progress

A trace is a tree of spans

Borrow the vocabulary of distributed tracing. A trace is one end-to-end execution — a user request through to the final answer — identified by a trace_id. A span is one unit of work within it, with a start time, end time, name, attributes and a parent_span_id. Because agents nest (a run contains steps, a step contains an LLM call which may trigger a tool call which may itself call an LLM), spans form a tree, and the tree is what lets you see *why* a run took 2.6 seconds or 14 steps.

A minimal agent trace for "what is the status of my order and when will it ship?" might look like: root span agent.run (2 640 ms) containing llm.call 820 ms (decides to search), tool.search 340 ms, llm.call 650 ms (decides to query the database), tool.database 120 ms, and llm.call 710 ms for final generation. Sum the children and you have the critical path; the difference to the parent is your own framework overhead.

One agent run as a span tree
User requestAgent run · 2 640 msLLM call · 820 msSearch tool · 340 msLLM call · 650 msDatabase tool · 120 msFinal generation · 710 msAnswer
UserLLMAgentToolDataDecisionHumanGuardrail

What a span records

A span with only a name and a duration tells you *where* time went. To debug an agent you need to know *what the model saw and what it decided*, which means capturing inputs and outputs, not just timings. The attributes below are the working minimum; anything less and the first non-trivial incident will send you adding them.

  • Input: for an LLM span, the exact messages sent — system prompt version, retrieved context, tool definitions, prior turns. For a tool span, the parsed arguments. Store by reference (content hash) when large.
  • Output: the raw model response including any tool-call request; the tool's return value including error payloads.
  • Tokens: prompt, completion and cached tokens per LLM span; the running total on the parent.
  • Cost: computed at span end from tokens × the model's price at the time, plus tool charges. Never recompute historical cost from today's prices.
  • Latency: start and end timestamps; time-to-first-token for streaming calls.
  • Errors and retries: exception type, status code, attempt number, backoff applied; each retry is its own child span so five 429s are visible as five spans, not one slow one.
  • State changes: which memory or scratchpad keys were written, which approval gate was passed, which branch a router chose. Without these, trajectory checks in Deterministic Evaluators have nothing to read.
  • Identity: trace_id, span_id, parent_span_id, session_id, user_id (hashed), model id, prompt version, dataset case id when running evals.

Instrumenting an agent loop

Instrumentation lives at the boundaries: wrap the model client and the tool dispatcher, and open a root span per run. Do it once, in your own thin layer, rather than sprinkling calls through the agent code. If you use OpenTelemetry the same spans flow to any backend; if you write your own, keep the schema close to OTel so you can migrate.

Spans at the two boundaries that matter: model calls and tool calls.
1import time, uuid, contextvars
2
3_current = contextvars.ContextVar("span", default=None)
4spans: list[dict] = []
5
6class span:
7 def __init__(self, name, kind, **attrs):
8 self.s = {"span_id": uuid.uuid4().hex, "parent_span_id": None,
9 "name": name, "kind": kind, "attrs": attrs}
10 def __enter__(self):
11 parent = _current.get()
12 self.s["parent_span_id"] = parent["span_id"] if parent else None
13 self.s["start_ms"] = time.time() * 1000
14 self.token = _current.set(self.s)
15 return self.s
16 def __exit__(self, exc_type, exc, tb):
17 self.s["end_ms"] = time.time() * 1000
18 if exc: self.s["error"] = f"{exc_type.__name__}: {exc}"
19 _current.reset(self.token)
20 spans.append(self.s)
21
22def call_model(client, messages, tools, prompt_version):
23 with span("llm.call", "llm", prompt_version=prompt_version, n_messages=len(messages)) as s:
24 r = client.chat(messages=messages, tools=tools)
25 s["attrs"].update(input=messages, output=r.raw,
26 tokens_in=r.usage.prompt, tokens_out=r.usage.completion,
27 cost_usd=price(r.model, r.usage))
28 return r
29
30def call_tool(registry, name, args):
31 with span(f"tool.{name}", "tool", input=args) as s:
32 out = registry[name](**args)
33 s["attrs"]["output"] = out
34 return out

Traces serve evals and production alike

The same span schema feeds three consumers. In evals, evaluators read spans to compute trajectory metrics and budgets. In debugging, an engineer walks the tree to find the first bad decision (Trace Inspection: Debugging from a Trace). In monitoring, aggregations over spans produce latency percentiles, cost per task and step-count distributions (Logging, Metrics and Alerts). Designing the schema once for all three avoids the common outcome of three incompatible logging formats.

Retention is a real decision: full inputs and outputs for every production trace are large and contain user data. A common compromise is full payloads for 7–30 days with PII redaction, sampled full traces retained longer for the dataset, and metrics-only aggregates kept indefinitely.

Key points

  • Trace = one run; span = one unit of work with a parent; the tree explains latency and step counts.
  • Instrument the two boundaries: model calls and tool calls, plus a root span per run.
  • Record inputs, outputs, tokens, cost, latency, errors, retries and state changes — not just timings.
  • Each retry is its own span; errors carry type and status.
  • Compute cost at span time from the price then, and store it.
  • One span schema serves evals, debugging and monitoring.

Trace viewer

Trace viewer
One agent run as a tree of spans. Click a span to inspect its input, output, tokens, cost, latency, errors and retries.
total 2640 mstokens 6,906llm time 2180 mstool time 460 ms
Span
Agent run · "Why is checkout slow for EU users?"
Latency
2640 ms
Input
user: Why is checkout slow for EU users since yesterday?
Output
Latency comes from the new fraud-check call (avg 900 ms) enabled for EU on 2025-05-03…
State change
steps 4/8 · cost $0.0182

Reading order when something is wrong: find the first span whose output is surprising, then look at exactly the input that span received. The bug is usually in the context the model saw, not in the model.

When to use — and when not to

Use it when
  • From the first prototype — retrofitting tracing after an incident is far more painful.
  • Any agent with tools, retries or more than one LLM call per request.
  • Whenever cost per task or p95 latency matters to the business.
Avoid it when
  • Do not store full payloads without redaction where traces contain PII or secrets.
  • Do not build a bespoke schema far from OpenTelemetry; you will want to switch backends.
  • Do not rely on the provider dashboard alone; it sees calls, not your tool spans or state changes.

Failure modes

  • Spans capture durations but not inputs; a wrong answer cannot be explained because nobody knows what the model saw.
  • Retries folded into one span; a 4-second call is actually five 429s and nobody notices the rate limit.
  • Cost recomputed from current prices; historical trend charts move when the vendor changes pricing.
  • No parent_span_id; the trace is a flat list and step nesting is lost.
  • Tracing sampled at 1% from day one; the failing run is never in the sample.