Tracing & observability

An agent does something wrong in production and the first question anyone asks is what it actually did. Without a record you are reconstructing it from impressions, and the incident turns into an argument. A trace is that record: every model call, every tool invocation and its arguments, every result, with cost and timing attached and one id threading the run together. This section covers what to capture, how to thread it, and how to keep it useful without storing customer data you should not be keeping.

The first question anyone asks#

When an agent misbehaves, the first question is always what it actually did. Without a trace you are guessing, and the incident becomes an argument about what people think happened.

A trace is the full record of one run: every model call, every tool invocation and its arguments, every result, tokens, cost, timing, and which step failed.

Three words, defined#

The vocabulary is small and the tools all use it, so it is worth having exactly. A span is one unit of work with a start time, an end time and some attributes: a model call, a retrieval, a tool invocation. A span has a parent, which is the span it happened inside, so spans form a tree. A trace is that tree for one request, identified by a run id that every span in it carries. That is all. Everything a tracing product sells you is a way to store, search and draw those three things.

The reason the tree matters rather than a flat list is that a flat list cannot tell you whether the second retrieval was a retry of the first or a separate step in a later turn, and that distinction is the whole difference between a bug report and an argument.

One id, threaded through#

The single most valuable thing you can add is a run identifier attached to every log line. Without it you have a pile of unrelated calls and no way to reassemble them.

log.info("llm_call", extra={
    "run_id": run_id,          # ties the whole run together
    "step": "extract",
    "turn": turn,
    "model": model,
    "input_tokens": usage.input_tokens,
    "output_tokens": usage.output_tokens,
    "cached_tokens": usage.cache_read_input_tokens,
    "cost_usd": cost,
    "latency_ms": elapsed,
    "stop_reason": response.stop_reason,
})

Threading that id by hand means adding a run_id parameter to every function between the request handler and the model call, including the ones that have no other reason to know about it, and it is abandoned in most codebases about two weeks in. The mechanism that survives is an ambient variable: in Python a contextvars.ContextVar, which is set once at the top of the request and read by anything below it, and which works correctly under asyncio because each task gets its own copy. That one detail is why the tracer below is forty lines rather than a parameter threaded through forty functions.

For tool calls, record the name, the arguments, whether it succeeded, the error if not, and the size of what came back. Result size matters because it predicts the cost of every turn after it.

The whole mechanism, in forty lines#

Tracing products are worth paying for and they are not magic, and knowing what they do makes choosing between them a different conversation. A span is a context manager that records when it opened, what it was told, when it closed and whether it closed by exception. The parent is whatever span was open when this one started.

import contextvars, json, time, uuid

current = contextvars.ContextVar("current_span", default=None)
SPANS = []

class Span:
    """One step of one request. It knows its parent, so a run reassembles into a tree."""
    def __init__(self, name, **attrs):
        self.id = uuid.uuid4().hex[:8]
        self.name, self.attrs = name, attrs
        self.parent = current.get()
        self.run_id = self.parent.run_id if self.parent else uuid.uuid4().hex[:8]
        self.error = None

    def __enter__(self):
        self.t0 = time.perf_counter()
        self.token = current.set(self)
        return self

    def __exit__(self, exc_type, exc, tb):
        self.ms = (time.perf_counter() - self.t0) * 1000
        current.reset(self.token)
        if exc is not None:
            self.error = f"{exc_type.__name__}: {exc}"
        SPANS.append(self)
        print(json.dumps({
            "run_id": self.run_id, "span_id": self.id,
            "parent_id": self.parent.id if self.parent else None,
            "step": self.name, "latency_ms": round(self.ms, 1),
            "error": self.error, **self.attrs,
        }))
        return False                      # never swallow the exception

def record(**attrs):
    """Attach a measurement to whichever span is currently open."""
    span = current.get()
    if span is not None:
        span.attrs.update(attrs)

Wrapping the model call is then a matter of opening a span and recording the usage fields the response already carries. The client here is a stub so the file runs offline; the field names are the ones the real response object uses.

PRICES = {"small": (1.00, 5.00), "large": (5.00, 25.00)}   # usd per million tokens

class StubClient:
    """Stands in for the real client so this file runs offline. The return value has
    the shape the Anthropic SDK gives you: .usage.input_tokens, .usage.output_tokens,
    .usage.cache_read_input_tokens, and .stop_reason."""
    def call(self, model, prompt_tokens, output_tokens, cached=0):
        time.sleep(0.002 + output_tokens / 40000)
        usage = type("Usage", (), {"input_tokens": prompt_tokens,
                                   "output_tokens": output_tokens,
                                   "cache_read_input_tokens": cached})()
        return type("Response", (), {"stop_reason": "end_turn", "usage": usage})()

client = StubClient()

def cost_usd(model, usage):
    price_in, price_out = PRICES[model]
    billed_in = usage.input_tokens - usage.cache_read_input_tokens
    return (billed_in * price_in
            + usage.cache_read_input_tokens * price_in * 0.1      # cache reads are cheap
            + usage.output_tokens * price_out) / 1e6

def llm(step, model, prompt_tokens, output_tokens, cached=0):
    with Span("llm:" + step, model=model):
        r = client.call(model, prompt_tokens, output_tokens, cached)
        record(input_tokens=r.usage.input_tokens, output_tokens=r.usage.output_tokens,
               cached_tokens=r.usage.cache_read_input_tokens,
               cost_usd=round(cost_usd(model, r.usage), 6),
               stop_reason=r.stop_reason)
        return r

def tool(name, fail=False, result_chars=0):
    with Span("tool:" + name):
        time.sleep(0.003)
        record(result_chars=result_chars, ok=not fail)
        if fail:
            raise TimeoutError("upstream did not answer in 5s")

Now a request that does what a real one does: a cheap planning call, a tool that times out and is retried, and an expensive answering call.

def handle(question, user, feature):
    with Span("request", user=user, feature=feature, question=question) as run:
        llm("plan", "small", prompt_tokens=900, output_tokens=60, cached=800)
        try:
            tool("search_docs", fail=True)
        except TimeoutError:
            tool("search_docs", result_chars=18000)      # the retry that succeeded
        llm("answer", "large", prompt_tokens=6200, output_tokens=420, cached=800)
        return run.run_id

run_id = handle("how do I rotate an API key", user="u_417", feature="support-chat")

spans = [s for s in SPANS if s.run_id == run_id]
root = next(s for s in spans if s.parent is None)
answer = next(s for s in spans if s.name == "llm:answer")
total = sum(s.attrs.get("cost_usd", 0) for s in spans)
print(f"\n{len(spans)} spans, {sum(1 for s in spans if s.error)} failed, "
      f"{root.ms:.0f} ms wall clock, {total * 100:.3f} cents")
print(f"the answer call is {100 * answer.attrs['cost_usd'] / total:.0f}% of the money "
      f"and {100 * answer.ms / root.ms:.0f}% of the time")

{"run_id": "188a3f41", "span_id": "3b2c8fd0", "parent_id": "b72663ed", "step": "llm:plan", "latency_ms": 4.5, "error": null, "model": "small", "input_tokens": 900, "output_tokens": 60, "cached_tokens": 800, "cost_usd": 0.00048, "stop_reason": "end_turn"}
{"run_id": "188a3f41", "span_id": "1982b840", "parent_id": "b72663ed", "step": "tool:search_docs", "latency_ms": 3.8, "error": "TimeoutError: upstream did not answer in 5s", "result_chars": 0, "ok": false}
{"run_id": "188a3f41", "span_id": "498155e8", "parent_id": "b72663ed", "step": "tool:search_docs", "latency_ms": 3.8, "error": null, "result_chars": 18000, "ok": true}
{"run_id": "188a3f41", "span_id": "b0a156fa", "parent_id": "b72663ed", "step": "llm:answer", "latency_ms": 15.4, "error": null, "model": "large", "input_tokens": 6200, "output_tokens": 420, "cached_tokens": 800, "cost_usd": 0.0379, "stop_reason": "end_turn"}
{"run_id": "188a3f41", "span_id": "b72663ed", "parent_id": null, "step": "request", "latency_ms": 27.6, "error": null, "user": "u_417", "feature": "support-chat", "question": "how do I rotate an API key"}

5 spans, 1 failed, 28 ms wall clock, 3.838 cents
the answer call is 99% of the money and 56% of the time

Five lines of JSON and the run is reconstructable by anyone, including the person who did not write it. The failed search and its retry both appear, which matters: a tracer that only records the successful attempt reports a healthy system that is quietly retrying half its requests.

Structured logs, not print statements#

The difference is not tidiness, it is whether the question you will want to ask is answerable. One JSON object per span, with the same keys every time, means the whole day's traces are a table: which steps failed and how often, which model calls have zero cached tokens, what the 99th percentile latency of the retrieval step is, what one user cost last week. A log line reading 'calling model for step extract, 6200 tokens' answers none of those without someone writing a parser, and the parser breaks the first time the sentence is reworded.

Two rules make the table usable. Keys are stable and typed: latency_ms is always a number of milliseconds, never sometimes seconds and never a string. And the message field is a short constant name such as llm_call rather than a sentence, with everything variable in its own key, so grouping by name works.

What the trace lets you answer#

• Which step is slow, and whether it is the model or a tool.
• Which step is expensive, and whether caching is working.
• Whether the agent is repeating itself.
• Whether the right documents were retrieved for a wrong answer.
• What the model was actually sent, which is often not what you think.

Privacy#

Traces contain user content by definition, so they are subject to the same retention and access rules as any other personal data. Redact what you must, set a retention period deliberately, and do not let convenience during development quietly become the production default.

The practical shape is two tiers. Metadata, meaning the token counts, costs, latencies, step names, error types and the run id, is small, contains nothing personal, and can be kept for a year without anyone worrying. Payloads, meaning the rendered prompt and the model's output, are large and personal, and a much shorter retention on those buys most of the debugging value at a fraction of the risk. Splitting the two is a decision to make when you build the tracer, because retrofitting it means rewriting every consumer of the data.

What to carry, and what to skip#

• Carry: span, parent, run id. Every tracing tool is those three ideas, and being able to say so is the difference between evaluating tools and being sold one.
• Carry: an ambient context variable is what makes the run id reach the bottom of the stack. Threading it as a parameter is the approach that gets abandoned.
• Carry: record cost where the usage numbers are, and record failed attempts as well as successful ones.
• Skip: choosing a vendor before you have instrumented anything. Forty lines of your own will tell you what you actually want from one.
• Skip: tracing at the function level. Spans belong at the steps you would name in a sentence describing the run, and a trace with two hundred spans per request is one nobody reads.

Tracing gives you a record of what the system did. This section is about what comes after that: deciding which traces are worth keeping, grouping failures so you are looking at a count rather than an anecdote, and turning each real failure into an eval case so it cannot come back unnoticed. Done regularly, this is what stops an eval set from being something you invented once and turns it into a description of what the system is actually asked to do.

What to keep#

Keeping every trace in full is expensive and usually unnecessary. Keep all failures and slow or costly runs, plus a random sample of normal ones, and everything for a period after any change.

Sampling has one rule that is easy to get wrong: the decision must be made once per run, at the top, and inherited by every span inside it. Sampling each span independently gives you traces with holes in them, which are worse than no trace at all because they look complete. Hash the run id and keep the run if the hash falls below the rate, which also means the same run is sampled or not consistently across services.

One table, and the questions it answers#

Once traces are structured, a day of them is a table with one row per run. Everything in this section is an aggregation of that table, so it is worth having one to work on. The rows below are synthetic and shaped like real traffic: three features with different turn counts, usage concentrated in a few heavy users, and a latency distribution with a tail.

import numpy as np
rng = np.random.default_rng(0)
N = 20000

# One row per run, the shape a day of traces actually has.
feature = rng.choice(["support-chat", "doc-summary", "code-review"], N, p=[.6, .3, .1])
w = 1.0 / (np.arange(1, 2001) ** 1.1)          # real usage is not uniform
user = rng.choice(2000, N, p=w / w.sum())
turns = np.where(feature == "code-review", rng.poisson(6, N) + 1, rng.poisson(1, N) + 1)
in_tok = turns * rng.integers(2000, 9000, N)
out_tok = turns * rng.integers(100, 700, N)
cost = (in_tok * 5.0 + out_tok * 25.0) / 1e6           # usd, large model rates
latency = turns * rng.lognormal(6.6, 0.55, N)          # ms

print("latency per run, milliseconds")
print(f"  mean {latency.mean():7.0f}   p50 {np.percentile(latency, 50):7.0f}"
      f"   p95 {np.percentile(latency, 95):7.0f}   p99 {np.percentile(latency, 99):7.0f}"
      f"   max {latency.max():7.0f}")
# latency per run, milliseconds
#   mean    2116   p50    1425   p95    6120   p99   11424   max   32633

Report percentiles, not averages, and pick the percentile from who is complaining. The p50 is what a typical user sees. The p95 is what an unlucky user sees several times a week and is usually where the complaints come from. The p99 is what an agentic run with five model calls hits routinely, because a run is only as fast as its slowest step and five draws from that tail is a different distribution from one. That last point is why agent latency surprises people: the tail multiplies.

Cost attribution#

A monthly bill is one number and tells you nothing you can act on. The same money split by feature and by user tells you where to spend engineering time, and the two splits usually point at different things.

print("\ncost attribution")
print("feature          runs   usd    share   usd per run")
for f in ("support-chat", "doc-summary", "code-review"):
    m = feature == f
    print(f"{f:15s}{m.sum():6d}{cost[m].sum():7.2f}{100*cost[m].sum()/cost.sum():7.1f}%"
          f"{cost[m].mean():12.4f}")

per_user = np.bincount(user, weights=cost)
order = np.sort(per_user)[::-1]
top1 = int(len(order) * 0.01)
print(f"\ntop 1% of users ({top1}) account for {100*order[:top1].sum()/cost.sum():.1f}% of spend")
print(f"the median user costs {np.median(per_user):.3f} usd, the heaviest {order[0]:.2f} usd")

cost attribution
feature          runs   usd    share   usd per run
support-chat    11944 892.06   47.9%      0.0747
doc-summary      6096 466.29   25.0%      0.0765
code-review      1960 504.07   27.1%      0.2572

top 1% of users (20) account for 54.1% of spend
the median user costs 0.147 usd, the heaviest 315.24 usd

Both halves of that change a decision. Per-run cost identifies the feature worth optimising, and it is not the one with the most traffic: shaving 20% off support-chat saves less than halving the number of turns code review takes. Per-user cost identifies whether you have a pricing problem rather than an efficiency problem, and a single user at 315 usd against a median of 0.15 is the kind of thing that is invisible in an aggregate and obvious in a trace. Recording user and feature on the root span costs two strings and is what makes either query possible; adding them afterwards means the last three months cannot be analysed.

What to alert on, and what only to record#

The distinction is whether a human should be woken. Record everything; alert only on something a person can act on now. The usual mistake is alerting on individual failures, which in any system with a normal background error rate produces a stream nobody reads, and the real incident then arrives as one more line in a channel everyone has muted.

# Background failure rate of 1%, rising to 6% at run 15000 when something breaks.
rate = np.where(np.arange(N) < 15000, 0.01, 0.06)
failed = rng.random(N) < rate
window = 500
roll = np.convolve(failed.astype(float), np.ones(window) / window, mode="valid")
over = np.flatnonzero(roll > 0.03) + window
print(f"\n{failed.sum()} failures in {N} runs")
print(f"alerting on each failure:              {failed.sum()} notifications")
print(f"alerting on the rate over {window} runs:    "
      f"crosses 3% at run {over[0]}, {over[0] - 15000} runs after the break")
print(f"windows above 3% before the break:     {(over < 15000).sum()}")
# 466 failures in 20000 runs
# alerting on each failure:              466 notifications
# alerting on the rate over 500 runs:    crosses 3% at run 15181, 181 runs after the break
# windows above 3% before the break:     0

The window is the only parameter and it trades one thing against one thing: a shorter window notices sooner and fires on noise, a longer window is quiet and slow. The 500-run window above waits 181 runs, and a 100-run window would have caught it sooner at the cost of firing on quiet periods where three failures happened to land together. Pick it from your traffic rate, so that the window covers a few minutes at your busiest and you are not alerting on a sample of four overnight.

• Alert on: error rate over a window, p95 latency above the number you promised, spend per hour above a ceiling, and a queue that is growing rather than draining.
• Alert on: cached tokens falling to zero across a deployment, which is a large and otherwise silent cost increase.
• Record only: individual failures, individual slow runs, token counts, per-user cost, tool result sizes. These are what you read when an alert fires, not reasons to fire one.
• Never alert on something with no action attached. An alert whose runbook is 'have a look' trains people to ignore alerts.

Look for patterns, not anecdotes#

One bad trace is a story. A hundred traces grouped by failure type is a priority list. Categorise failures, count them, and fix the largest category first.

kinds = ["tool_timeout", "empty_retrieval", "max_tokens", "schema_invalid", "refusal"]
idx = rng.choice(5, failed.sum(), p=[.42, .27, .16, .10, .05])
counts = np.bincount(idx, minlength=5)
print("\nfailures grouped, largest first")
running = 0
for k in np.argsort(-counts):
    running += counts[k]
    print(f"  {kinds[k]:16s}{counts[k]:5d}{100*counts[k]/counts.sum():7.1f}%"
          f"   cumulative {100*running/counts.sum():5.1f}%")
# failures grouped, largest first
#   tool_timeout      212   45.5%   cumulative  45.5%
#   empty_retrieval   104   22.3%   cumulative  67.8%
#   max_tokens         80   17.2%   cumulative  85.0%
#   refusal            36    7.7%   cumulative  92.7%
#   schema_invalid     34    7.3%   cumulative 100.0%

The categories come from reading traces, and the first pass is done by hand: read fifty failures, write down what went wrong in a few words each, and the categories will name themselves. Automate the classification afterwards, once the labels exist, rather than inventing labels in advance. A category with one member is a note, not a category.

Traces become eval cases#

User feedback#

Thumbs up and down, corrections, and whether a user retried or abandoned are cheap signals attached to real traces. They are noisy and biased towards people who bother to click, and they point you at where to look.