Tracing: is every call on the receipt?

A trace is the record of one request, step by step. This chapter traces a small RAG assistant, three ways, and compares each time what the traces recorded with what the model provider billed. The first two ways are shortcuts, and each one hides most of the cost in a different way. It covers what a trace and a span are, the two ways spans go missing, the fix, and two checks that catch both.

The source is Lab 14 (Observability), script 01_tracing.py, Exercise 2 ("is every step recorded?"), rerun for the video in October 2026. Every call is a real OpenAI API call. The course site, its questions and its articles are test data. The lab's other parts of script 01 (an agent's trace, what tracing costs, and handing spans to OpenTelemetry) aren't in the video; a short section below gives their numbers. The rest of the lab follows: a week of traffic and alerts in chapter 41, feedback and traces turned into tests in chapter 42, and finding causes in traces in chapter 43.

A trace is a receipt

A log line says something happened: request r0003 done in 1.82 s. A trace is more like an itemized receipt. It lists every step inside the request, with its time and its cost.

• A span is one step, from its start to its end, with whatever it recorded: the model, how many tokens it read and wrote, the cost, the passages search returned.
• Spans nest. The embedding sits inside search, search inside the assistant, the assistant inside the request.
• Add a trace's spans up (a rollup) and you get one number per request: its cost, its tokens, its model calls.

Tokens are pieces of words, and model calls are priced by the token. Open the spans of one recorded question:

The assistant: three calls per question

The assistant answers learners' questions about seven short articles on AI engineering. Each question makes three billed calls:

1. Search. The question is turned into a list of numbers, an embedding (text-embedding-3-small), which finds the 3 closest passages.
2. The answer. A small model, gpt-5.4-nano, writes it from those passages.
3. The judge. A bigger model, gpt-5.4-mini, checks whether the answer is supported by the passages: good or bad.

The test sent 30 questions under each of three tracing setups. The bill comes from the API, not from the traces: each OpenAI reply reports how many tokens the call used, and the lab prices them at list price. For the first setup, 30 questions cost 1.63¢.

Setup	Calls billed	Calls recorded	...inside their question's trace	Questions with all 3 calls	Bill in the questions' traces
only the main call traced	90	30	30	0 of 30	22%
every call traced, judge in a worker thread	90	90	60	0 of 30	22%
every call traced, context passed to the worker	90	90	90	30 of 30	100%

Shortcut 1: trace only the main call

The first setup traced the call that writes the answer. The search step had a span too, but the embedding call inside it went through a plain, untraced client, and so did the judge. Two of the three calls were billed and in no trace.

The traces recorded 0.36¢ of the 1.63¢ bill: 22%. The bill was 4.5× what the traces showed.

Which call was missing the money? The judge: 78% of the bill. The embedding was almost free (about 0.0008¢ for all 30). The judge isn't expensive because it does more work: across the 30 questions it read 11,919 tokens and wrote 821, and the answer read 9,309 and wrote 1,414. At nano's prices the judge would have cost less than the answer. It's the price: mini costs 3.75× nano per token read and 3.6× per token written.

That's the usual shape of the gap. Auto-instrumentation that wraps only the main model client misses every other call: embeddings, judges, rerankers, retries, background jobs. Those are often the expensive ones.

Shortcut 2: the judge in a worker thread

So the second setup traced every call, and ran the judge on the side, in a thread pool, so that in a real app the learner wouldn't wait for it.

All 90 calls were recorded, and the traces held 100% of the bill. But each of the 30 judge spans landed in a trace of its own, attached to no question. The questions' own traces still held 22% (between 15% and 28% each); the judge's 78% sat in 30 traces of their own.

Why? The tracer keeps the current span in a context variable, like a hidden ticket that says which request a step belongs to. Each new span reads the ticket to find its parent:

# tracing.py, simplified
_current = contextvars.ContextVar("current_span", default=None)

@contextmanager
def span(self, name, attributes=None):
    parent = _current.get()
    if parent is None:          # no ticket: start a new trace
        s = Span(new_trace_id(), new_span_id(), None, name)
    else:                       # nest under the current span
        s = Span(parent.trace_id, new_span_id(), parent.span_id, name)
    token = _current.set(s)
    try:
        yield s
    finally:
        _current.reset(token)
        self.exporter.export(s)

Within one thread, every step copies the ticket from the step before. A new thread starts with an empty context. The judge's span finds no current span, so it starts a new receipt.

The fix: pass the ticket

When the code hands work to the worker, it hands over the ticket too: run the work in a copy of the caller's context.

# 01_tracing.py, Exercise 2
ctx = contextvars.copy_context()
pool.submit(ctx.run, online_judge, question, docs, answer, tracer, client)

Now all 90 calls landed in their question's trace, and all 30 questions were complete. The lab keeps a test that pins the trap down: a span opened in a worker thread without the copied context starts a new trace. Pair it with one that checks your own workers land in the request's trace, so the mistake can't quietly come back. The same goes for any place work changes threads or tasks: a thread pool, a queue consumer, a callback. Python's asyncio tasks copy the context when they're created, but a plain threading.Thread or a pool worker doesn't.

Pick a setup to see where each question's three calls went, and what the two checks say:

How to notice: two checks

In real traffic, nobody tells you what's missing. Two checks find it:

• Check 1: calls traced vs. calls billed, model by model. In the first setup, the embedding and the judge have 0 of 30 traced: caught. In the second, every call is there, so the check passes and misses the problem.
• Check 2: questions whose trace holds every call they should. With the judge on the side, 0 of 30 have all three: caught. It catches both shortcuts.

Check 2 needs to know how many calls a question should make, which changes with the design (an agent's number of steps varies). Check 1 needs only the bill. Run both, every week, on real traffic.

Also in the lab

These parts of script 01 aren't in the video. From the lab's README (its own run, October 2026):

• An agent's trace. Lab 09's refund agent on one task: 6 model calls and 5 tool calls in 5.9 s, $0.00161. 96% of its tokens were input (6,557 of 6,795), because every step resends the conversation so far.
• What tracing costs a request. Per span, in the request's thread: 5.5 µs in memory, 435 µs writing each span to SQLite as it ends, 3.6 µs batched from a background thread. A request (median 1.25 s, 4 spans) pays about 15 µs batched, 0.001%.
• What it costs to keep. 6.4 KB a request with the prompts and answers, 1.8 KB without. The text is most of the bytes, and it's user data: record it on purpose, with a retention period and access control.
• OpenTelemetry. All 197 spans went through the real OpenTelemetry SDK with their ids, parents, times and attributes intact. The lab names its attributes by OpenTelemetry's GenAI conventions (gen_ai.request.model, gen_ai.usage.input_tokens), so any tool that reads OpenTelemetry can take them.
• A batch needs a flush. In the lab's saved live run, 20 requests of 4 spans each left 78 spans, not 80: the last request lost its two. The batching exporter writes from a background thread, and the script exited without calling shutdown(), so the spans still in its queue were dropped. The video's notes found this in the data; it isn't in the README.

What to do

• Trace every call, not only the main model client: embeddings, judges, rerankers, tool calls, background work.
• Pass the context wherever work changes threads or tasks, and keep a test that fails when it isn't passed.
• Reconcile traces with the bill, model by model (check 1), and check that every request's trace is whole (check 2).
• Record cost on every model-call span, from the reply's token counts, so a rollup gives cost per request.
• Flush the exporter on shutdown.

Caveats

• Thirty test questions. The gap's size, 78%, belongs to this assistant: one cheap answer and one pricier judge. The shape is general: whatever isn't traced is invisible, and the expensive call is often not the main one.
• The bill is list price × reported tokens. It's read from the API's own replies, independently of the traces, but it isn't an invoice: discounts and cached-token prices aren't in it.
• Three separate runs. Each setup is its own run of the same 30 questions, so the bills differ slightly (1.63–1.65¢), and so do the per-question shares.
• The recording waited for the judge. It called .result() right after submitting the judge, so the request didn't actually save time. A real app would let the judge finish later; the context still has to be passed.
• A from-scratch tracer. The trap is the same with OpenTelemetry's Python SDK, which also keeps the current span in a context variable.

The checklist

1. List every billed call a request makes, by endpoint and model, and trace each one.
2. Put the token counts and cost on every model-call span.
3. Copy the context into every thread pool, worker and callback, and test it.
4. Each week, compare calls traced with calls billed, model by model.
5. Each week, count requests whose trace is complete, and look at the ones that aren't.
6. Decide what text to record, for how long, and who can read it.
7. Flush the exporter before the process exits.

Practice: a tracer that keeps the ticket

Write the lab's tracer from scratch: spans that nest through a context variable, a worker that does or doesn't get the ticket, a rollup, and the two checks. The tests run the assistant's three setups on the recorded costs of all 30 questions and expect the lab's numbers: 22% and 78%, then 30 traces of their own, then 30 of 30 complete. Real threads don't run in the browser's Python, so the worker is imitated the way a new thread behaves: running in an empty contextvars.Context().

Quiz

Check your understanding

Try each question before opening its answer.

What's the difference between a log line and a trace?

A log line says something happened: the request took 1.82 s. A trace is the request as a tree of spans, each step with its start, end and what it recorded (model, tokens, cost), so it says which step took the time and which call cost the money.

Your traces say this week cost $1,200; the provider bills $4,800. Where do you look?

At every call that isn't the main model call: embeddings, judges, rerankers, retries, background jobs. Compare call counts by endpoint and model with the bill. In the lab, tracing only the main call missed the judge, which was 78% of the bill.

Why was the judge 78% of the bill when it read and wrote about as many tokens as the answer?

Its model costs more: mini is 3.75× nano per token read and 3.6× per token written. At nano's prices the judge's tokens would have cost less than the answer's.

Every call was recorded, yet the questions' traces held 22%. How?

The judge ran in a worker thread. The current span lives in a context variable, and a new thread starts with an empty context, so each judge span found no parent and started a trace of its own: 30 traces attached to no question.

How do you fix it, and keep it fixed?

Submit the work in a copy of the caller's context: pool.submit(contextvars.copy_context().run, fn, …). Keep a test that fails when a worker starts a new trace, as the lab does.

Why run two checks instead of one?

Comparing calls traced with calls billed catches calls that aren't traced, but passes when they're traced into the wrong trace. Counting complete request traces catches both (0 of 30 in each shortcut), but needs to know how many calls a request should make. The first needs only the bill.

Next up: Chapter 41 runs a whole week of traffic with four problems planted in it, puts it on a dashboard, and scores alert rules on which problems they caught, how fast, and how often they fired for nothing.