Part V · Build it

Lab 9: tracing and cost

Build a small tracer: every model call becomes a span with its model, tokens, cost, latency and stop reason, spans nest so a run's steps form a tree, and each span is written as one line of JSON with personal data masked first. Then summarise a run, and add a budget guard that refuses a call before it could push the run past a spending cap.

What you will build

One file, labs/09-tracing/tracing.py, of about 380 lines, and its tests in labs/09-tracing/test_tracing.py. Runs are written to labs/09-tracing/traces/, which git ignores. The pieces:

• Tracer.span(name), a context manager that opens a span; spans nest.
• A listener on the shared adapter that turns every llm.chat() call into a span of its own.
• Masking with Lab 7's mask, plus exact masking by key name, before anything is written.
• summary: calls, tokens, cost, p50 and p95 latency, and the span tree with costs rolled up to every parent.
• BudgetGuard, which raises before a call when the run's spend plus that call's worst case would pass a cap.

Before you start

Finish Lab 0. The lab imports the masker from labs/07-guardrails/guardrails.py, so that folder must be present; you do not need to have done Lab 7 first, though step 4 makes more sense if you have. Any backend works, and the outputs on this page come from the fake backend:

export LLM_BACKEND=fake

On the fake backend a call takes a few microseconds, so every latency on this page is tiny. Read the shape of the tree and the token counts; the times only mean something on a real model.

Step 1: a span is a context manager

A trace is a tree of spans, and a span is one piece of work: a name, a start, a duration, some attributes, and the id of its parent, the work that started it (chapter 45). Python's with statement has exactly that shape: something happens on the way in, the work runs, and something happens on the way out, even if the work raises.

@contextmanager
def span(self, name, **attrs):
    parent = self._current.get()             # the span we are inside, if any
    span_id = uuid.uuid4().hex[:8]
    token = self._current.set(span_id)       # spans opened inside this one see it as parent
    wall, started = time.time(), time.perf_counter()
    status = "ok"
    try:
        yield attrs
    except BaseException as exc:
        status = f"error: {type(exc).__name__}"
        raise
    finally:
        self._current.reset(token)
        self._write({"span_id": span_id, "parent_id": parent, "name": name, "kind": "span",
                     "start": wall, "duration_s": time.perf_counter() - started,
                     "status": status, "attrs": attrs})

The current span lives in a context variable, not a global. Code that runs inside a with block sees the innermost open span, and asyncio tasks started inside it inherit it, so parallel branches land under the right parent and two users' requests never mix. The duration comes from time.perf_counter(), a clock made for measuring intervals; the start comes from time.time(), so a person can tell when the span happened.

Step 2: every model call becomes a span

The shared adapter calls every function registered with llm.add_listener after each call, with the request and the reply. The tracer registers one, so every model call in the run is recorded without touching the code that makes it:

def _on_call(self, request, reply):
    """Called by llm.chat after every call: the span ends now and began latency_s ago."""
    now = time.time()
    self._write({
        "span_id": uuid.uuid4().hex[:8], "parent_id": self._current.get(),
        "name": f"llm {reply.model}", "kind": "llm",
        "start": now - reply.latency_s, "duration_s": reply.latency_s, "status": "ok",
        "attrs": {
            "backend": reply.backend, "model": reply.model,
            "input_tokens": reply.input_tokens, "output_tokens": reply.output_tokens,
            "cost_usd": reply.cost_usd, "latency_s": reply.latency_s,
            "stop_reason": reply.stop_reason, "max_tokens": request["max_tokens"],
            "effort": request["effort"],
            "tool_calls": [c.name for c in reply.tool_calls],
            "input": preview(_last_input(request["messages"])), "output": preview(reply.text),
        },
    })
    if self.guard:
        self.guard.record(reply)

The listener runs when the call has finished, so the span's start is worked out backwards: now, minus the latency the adapter measured. Its parent is whatever span was open when llm.chat() was called. Keep stop_reason beside max_tokens: on Claude the thinking counts toward max_tokens, and a rise in max_tokens stops after a change is the trace telling you replies are being cut off (chapter 45).

Step 3: one JSON line per span

A file with one JSON object per line is a trace store you can search with grep and turn back into a tree with a few lines of code. Each span is written when it ends, so children reach the file before their parents. This is the first line of the demo run's file:

{"trace_id": "41595362c1f34a47", "span_id": "ffb1449c", "parent_id": "740e2db6", "name": "llm fake", "kind": "llm", "start": 1793633253.9371805, "duration_s": 1.325004268437624e-05, "status": "ok", "attrs": {"backend": "fake", "model": "fake", "input_tokens": 48, "output_tokens": 45, "cost_usd": 0.0, "latency_s": 1.325004268437624e-05, "stop_reason": "end", "max_tokens": 1024, "effort": "low", "tool_calls": [], "input": "List the parts of this trip to plan: I'm going from Leeds to Edinburgh on 14 March for two nights. Send the plan to <EMAIL_A> or text <PHONE_A>.", "output": "[fake model] You said: List the parts of this trip to plan: I'm going from Leeds to Edinburgh on 14 March for two nights. Send the plan to <EMAIL_A> or text <PHONE_A>."}}

The model call above took 13 microseconds, because the fake backend answers from memory. Tracing must never break the run it watches: if a span cannot be written (a full disk, an attribute that will not serialise), _write drops it and adds one to tracer.dropped, and the run carries on. The budget guard in step 6 takes the opposite view, on purpose.

Step 4: mask before you write

Traces copy prompts and replies, and prompts carry whatever users typed. A trace store that keeps them is a second copy of your users' data, often kept longer and read by more people than the first. So mask before writing, not when displaying (chapter 45). Two methods, one exact and one not:

SENSITIVE_KEYS = {"name", "full_name", "email", "phone", "address", "card_number",
                  "password", "api_key", "token", "secret", "cookie"}

def scrub(value):
    if isinstance(value, str):
        return mask(value).text                  # Lab 7's detector
    if isinstance(value, dict):
        return {k: "<masked>" if str(k).lower() in SENSITIVE_KEYS else scrub(v)
                for k, v in value.items()}
    if isinstance(value, (list, tuple)):
        return [scrub(v) for v in value]
    return value

• By key name, exact. A value stored under email or api_key is replaced whole, whatever it looks like. The names are matched exactly. A rule such as "any key containing token" looks safer, and would also hide input_tokens and output_tokens, the counts you most need.
• By content, a detector. Every other string goes through mask, which finds emails, phone numbers and card numbers in free text. It is only as good as Lab 7's harness says it is: a phone number written as 555-010-0142 will reach the trace in clear.

The previews of a call's input and output are cut to 200 characters, and the order matters: mask first, then cut. Cut first, and an email address split at the 200th character leaves a fragment such as sam.tay that the masker no longer recognises. The demo's question holds an email and a phone number; the line in step 3 shows both as placeholders, and two tests read back the files they wrote and check that the raw values are absent.

Step 5: summarise a run

summary reads a trace file back and prints the totals, the latency percentiles and the tree. Two ideas carry the weight.

Percentiles. An average latency hides the slow calls users notice. The p50 (median) says what a typical call takes and the p95 what the slowest one in twenty takes (chapter 45). The code uses the nearest-rank method: sort, then take the value at rank ⌈p/100 × n⌉, counting from 1.

def percentile(values, p):
    ordered = sorted(values)
    rank = max(1, math.ceil(p / 100 * len(ordered)))
    return ordered[rank - 1]

Worked, on five latencies of 0.5, 0.1, 0.4, 0.2 and 0.3 seconds: sorted, 0.1, 0.2, 0.3, 0.4, 0.5. For p50 the rank is ⌈0.5 × 5⌉ = ⌈2.5⌉ = 3, so 0.3 s. For p95 it is ⌈0.95 × 5⌉ = ⌈4.75⌉ = 5, so 0.5 s, the slowest call. With 20 calls the p95 is the 19th smallest. With a handful of calls the p95 is simply the maximum, so do not read much into it until you have hundreds.

Rolling costs up. Each span in the tree shows the tokens and cost of every model call beneath it, added up through the parents, so the root shows the whole run and each step shows its share (cost rollup). That is where to look first when a run costs more than it should.

Step 6: a budget guard that fails closed

A loop that calls a model can run away: an agent that never decides it is done, a retry that retries forever. A spending cap turns that into an error (chapter 45). The guard has to decide before the call, when the cost is not yet known, so it uses the worst case:

The input estimate is deliberately pessimistic, three characters per token rather than four, so the guard overcounts rather than under. The output side assumes the model writes all of max_tokens, which on Claude includes thinking. If the run's spend so far plus that worst case would pass the cap, the call is refused and never sent:

def check(self, messages, system, max_tokens, model):
    worst = self.worst_case(messages, system, max_tokens, model)
    if self.spent + worst > self.cap:
        raise BudgetExceeded(f"spent ${self.spent:.6f} + this call at most ${worst:.6f} "
                             f"would pass the cap of ${self.cap:.6f}")
    return worst

Worked, from the capped demo below. Three calls have run, 236 input and 155 output tokens at Haiku's prices: 236 × 0.10 / 1,000,000 + 155 × 0.50 / 1,000,000 = $0.000101 spent. The last call's request is 521 characters, so the guard counts ⌈521 / 3⌉ = 174 input tokens, and it asks for up to 2,048 output tokens: 174 × 0.10 / 1,000,000 + 2,048 × 0.50 / 1,000,000 = $0.000017 + $0.001024 = $0.001041. Then $0.000101 + $0.001041 = $0.001142, more than the $0.001 cap, so the call is refused.

The guard fails closed three ways, and each has a test:

• It refuses to start without a positive cap, or with a price_model missing from the price table, because it could not price a call. Calls on a model with no price, such as the fake backend or Ollama, are priced as price_model (Haiku by default), which is how you can test the guard offline.
• A refused call is never sent: the test checks that the fake backend received nothing.
• A call that raised after it was sent may still have been billed, so its worst case stays counted as spent.

Note the contrast with step 3. When tracing fails, the run goes on, because a missing span hurts nobody. When the guard is unsure, the run stops, because an unchecked call can cost money. Decide which way each piece of your system should fail, and test that it does.

Step 7: trace a run

The demo is a small travel planner in four model calls: understand the request, research the train and the hotel, write the plan. Each step is a span, and the question carries an email address and a phone number.

$ LLM_BACKEND=fake python labs/09-tracing/tracing.py demo
trace: labs/09-tracing/traces/20261102-205733-demo-415953.jsonl
calls: 4 (fake); tokens: 366 in, 210 out
cost: $0.000000 as run; on claude-haiku-5-5 these tokens cost $0.000142
latency per call: p50 0.008 ms, p95 0.013 ms
plan-trip  0.86 ms  (under it: 366 in / 210 out  $0.000000)
├─ understand  0.23 ms  (under it: 48 in / 45 out  $0.000000)
│  └─ llm fake  48 in / 45 out  $0.000000  0.01 ms  stop=end
├─ research  0.33 ms  (under it: 188 in / 110 out  $0.000000)
│  ├─ research-train  0.12 ms  (under it: 94 in / 55 out  $0.000000)
│  │  └─ llm fake  94 in / 55 out  $0.000000  0.01 ms  stop=end
│  └─ research-hotel  0.11 ms  (under it: 94 in / 55 out  $0.000000)
│     └─ llm fake  94 in / 55 out  $0.000000  0.01 ms  stop=end
└─ write  0.16 ms  (under it: 130 in / 55 out  $0.000000)
   └─ llm fake  130 in / 55 out  $0.000000  0.01 ms  stop=end

Read it top down. Each model call hangs under the step that made it, and each step shows what the calls beneath it used. The fake backend costs nothing, so the cost column is zero; the second line prices the same tokens on claude-haiku-5-5. The latencies are hundredths of a millisecond: on a real model each call takes far longer, and the slowest step stands out. Now the same run with a cap:

$ LLM_BACKEND=fake python labs/09-tracing/tracing.py demo --cap 0.001
stopped: spent $0.000101 + this call at most $0.001041 would pass the cap of $0.001000
trace: labs/09-tracing/traces/20261102-205733-demo-76a881.jsonl
calls: 3 (fake); tokens: 236 in, 155 out
cost: $0.000000 as run; on claude-haiku-5-5 these tokens cost $0.000101
latency per call: p50 0.007 ms, p95 0.007 ms
refused by the budget guard: 1
plan-trip  0.77 ms  (under it: 236 in / 155 out  $0.000000)  [error: BudgetExceeded]
├─ understand  0.28 ms  (under it: 48 in / 45 out  $0.000000)
│  └─ llm fake  48 in / 45 out  $0.000000  0.01 ms  stop=end
├─ research  0.32 ms  (under it: 188 in / 110 out  $0.000000)
│  ├─ research-train  0.12 ms  (under it: 94 in / 55 out  $0.000000)
│  │  └─ llm fake  94 in / 55 out  $0.000000  0.01 ms  stop=end
│  └─ research-hotel  0.12 ms  (under it: 94 in / 55 out  $0.000000)
│     └─ llm fake  94 in / 55 out  $0.000000  0.01 ms  stop=end
└─ write  0.05 ms  [error: BudgetExceeded]
   └─ REFUSED  spent $0.000101 + this call at most $0.001041 would pass the cap of $0.001000
guard: cap $0.001000, spent $0.000101 (priced as claude-haiku-5-5)

The refusal is in the trace too, under the step that asked, and the error marks every span it passed through on its way out. summary reads any trace back, the newest by default:

$ python labs/09-tracing/tracing.py summary
trace: labs/09-tracing/traces/20261102-205733-demo-76a881.jsonl
calls: 3 (fake); tokens: 236 in, 155 out
cost: $0.000000 as run; on claude-haiku-5-5 these tokens cost $0.000101
latency per call: p50 0.007 ms, p95 0.007 ms

(The tree that follows is the same as above.)

Checklist

• I opened nested spans and saw each one record its parent.
• I can explain how a model call becomes a span without changing the code that makes it.
• I read a trace file and found why children come before their parents.
• I checked that no email or phone number from the demo reached the trace file.
• I worked a p50 and a p95 by hand with the nearest-rank method.
• I worked out by hand why the capped demo refused its last call.
• The lab's tests pass.

Run it

The tests cover nesting, the model-call spans and their fields, the JSON lines, an error inside a span, removing the listener, masking by key and by content (and masking before cutting), dropped writes, the rollup, percentiles, the summary tree, and the budget guard: it refuses before sending, lets calls through under the cap, stops a run as spend builds up, refuses to start without a price, and keeps a failed call's worst case. Every test writes to a temporary folder. From labs/:

$ python -m pytest 09-tracing
...................                                                      [100%]
19 passed in 0.04s

Then, from the repository root:

python labs/09-tracing/tracing.py demo
python labs/09-tracing/tracing.py demo --cap 0.001
python labs/09-tracing/tracing.py summary
grep -c "example.com" labs/09-tracing/traces/*.jsonl     # 0 in every file

What it costs. The demo makes four calls. On the fake backend the token counts are estimates at about four characters per token: 366 input and 210 output tokens, which on claude-haiku-5-5 is 366 × 0.10 / 1,000,000 + 210 × 0.50 / 1,000,000 = $0.000142. Real replies are longer and include thinking, so take the ceiling too: three calls with max_tokens 1,024 and one with 2,048, 5,120 output tokens in all, give 366 × 0.10 / 1,000,000 + 5,120 × 0.50 / 1,000,000 = $0.0026 at most, about a quarter of a US cent. Ollama and the fake backend cost nothing.

Experiments

1. Trace a real model. Run the demo on Claude or Ollama. Which step is slowest? How far apart are p50 and p95? Compare each call's output tokens with its max_tokens.
2. Cut a reply off. Set the write step's max_tokens to 64 and run on Claude. Find stop=max_tokens in the tree. How would you spot this across a thousand runs?
3. Find the cap's edges. Work out by hand the smallest cap that lets the whole demo finish on the fake backend, then check it. Then find a cap that refuses the very first call.
4. Leak on purpose. Change the demo's question to give the phone number as 555-010-0142. Is it masked in the trace? What does that tell you about masking by detector?
5. A bigger model. Run with LLM_MODEL=claude-sonnet-5-5 and the same cap. How many calls does the guard allow now, and why?
6. Standard names. Rename the attributes to OpenTelemetry's GenAI conventions (gen_ai.request.model, gen_ai.usage.input_tokens, and so on) and update summary to match (chapter 45).

Going further

• Send spans to a tracing tool. Replace _write with an OpenTelemetry exporter and view your runs in a tool such as Langfuse or Arize Phoenix. Send in the background, so a slow collector never slows a request.
• Time to first token. With streaming, record when the first token arrived as well as when the last did; users feel the first.
• Sampling. At high volume, keep every trace with an error, a refusal or a high cost, and a random tenth of the rest (chapter 45).
• Reserve and settle. With calls running in parallel, two calls can both pass the check before either has spent. Add each call's worst case to a "reserved" total at the check and release it when the call settles.
• Score the traces. Run Lab 8's judge on a sample of traced answers and store the verdict on the trace.