Why did that answer take five seconds?
A support assistant plans, calls two tools, asks a model again and checks its reply. A user waits five seconds, and the bill is higher than planned. Which step was slow, and which one cost the money?
Module 69 traced one call. This lesson goes further: a whole agent run, with tokens, cost and failures on each step.
By the end of this lesson
Note
I can trace a request through an AI feature and read the trace to find what was slow, costly or failing.
Key words
| Word | What it means | Example |
|---|---|---|
| Span id | the id of one span | |
| Parent span id | the id of the span that holds this one | |
| Status | whether a span ended well or with an error | error |
| Tool span | a span for one tool an agent called | |
| Token count | how many tokens went in or came out | |
| Open standard | a shared design anyone may use |
The cells students fill in are left blank in this preview.
A span holds ids, times and facts
Each span has a span id and the trace id of its request. It names its parent with a parent span id, which is empty for the root.
It has a name, a start, an end and a status: ok or error. Facts go in its attributes. OpenTelemetry keeps times in nanoseconds since 1970. This lab keeps milliseconds from the start, so the numbers stay short.
Worked example: one model call span
| Field | Value |
|---|---|
| trace_id | 7a3f0c1d00000000000000000000aa01 |
| span_id | 0000000000000005 |
| parent_span_id | 0000000000000001 |
| name | model: answer |
| start and end | 3100 and 4900 |
| status | ok |
| attributes | model m-small-2026-08, input_tokens 2100, output_tokens 300, fallback true |
The cells students fill in are left blank in this preview.
What a model call span records
Record the model and its version, because a new version can change speed and cost. Record the input and output token counts and the time taken. Record whether the call was retried or fell back to another model.
Never put personal data on a span in plain text. Module 86, in the lesson Logging safely in an AI app, shows how to keep it out.
An agent adds a span for each tool
An agent does more than call a model. It plans, calls tools, then asks the model again. Give each tool call its own tool span, a child of the request span.
A tool span records the tool's name, its time and its status. A tool that fails shows as an error inside a request that may still end well.
Write the model helper, part 1
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'const base = process.env.AI_URL || \"http://ai:4000\";' '// The token counts of a reply, or null when the reply carries none.' 'function count(data, name) {' ' return data.usage && typeof data.usage[name] === \"number\" ? data.usage[name] : null;' '}' > model.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the model helper, part 2
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function ask(messages, sample, max) {' ' try {' ' const res = await fetch(base + \"/v1/chat/completions\", {' ' method: \"POST\",' ' headers: { \"content-type\": \"application/json\", authorization: \"Bearer lab\" },' ' body: JSON.stringify({ model: \"lab\", messages: messages, max_tokens: max || 100 }),' ' signal: AbortSignal.timeout(30000),' ' });' ' if (res.ok === false) throw new Error(\"status \" + res.status);' ' const data = await res.json();' ' const text = data.choices[0].message.content;' ' return { text, inTokens: count(data, \"prompt_tokens\"), outTokens: count(data, \"completion_tokens\"), recorded: false };' ' } catch (error) {' ' console.log(\"Recorded sample: no model answered (\" + error.message + \").\");' ' return { text: sample, inTokens: null, outTokens: null, recorded: true };' ' }' '}' 'module.exports = { ask };' >> model.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the agent trace, part 1
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'const { ask } = require(\"./model\");' 'const TRACE = \"7a3f0c1d00000000000000000000aa01\";' 'const PRICES = { \"m-large-2026-09\": [3, 15], \"m-small-2026-08\": [1, 4] };' 'const spans = [];' 'function sid(n) { return String(n).padStart(16, \"0\"); }' 'function span(n, parent, name, start, end, status, attributes) {' ' spans.push({ trace_id: TRACE, span_id: sid(n), parent_span_id: parent ? sid(parent) : \"\",' ' name, start, end, status, attributes });' '}' > trace2.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the agent trace, part 2
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'span(1, 0, \"agent request\", 0, 5000, \"ok\", {});' 'span(2, 1, \"model: plan\", 0, 800, \"ok\", { model: \"m-large-2026-09\", input_tokens: 900, output_tokens: 60 });' 'span(3, 1, \"tool: find order\", 800, 1100, \"ok\", { tool: \"find_order\" });' 'span(4, 1, \"tool: delivery date\", 1100, 3100, \"error\", { tool: \"delivery_date\" });' 'span(5, 1, \"model: answer\", 3100, 4900, \"ok\", { model: \"m-small-2026-08\", input_tokens: 2100, output_tokens: 300, fallback: true });' 'span(6, 1, \"check reply\", 4900, 5000, \"ok\", {});' 'function kids(id) { return spans.filter(function (s) { return s.parent_span_id === id; }); }' 'function took(s) { return s.end - s.start; }' >> trace2.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the agent trace, part 3
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'function cost(a) {' ' const p = PRICES[a.model];' ' return p ? a.input_tokens * p[0] + a.output_tokens * p[1] : 0;' '}' 'function show(id, depth) {' ' for (const s of kids(id)) {' ' const flag = s.attributes.fallback ? \", fell back\" : \"\";' ' console.log(\" \".repeat(depth) + s.name + \" \" + took(s) + \" ms \" + s.status + flag);' ' show(s.span_id, depth + 1);' ' }' '}' >> trace2.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the agent trace, part 4
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function main() {' ' console.log(\"trace \" + TRACE);' ' show(\"\", 0);' ' const leaves = spans.filter(function (s) { return kids(s.span_id).length === 0; });' ' leaves.sort(function (a, b) { return took(b) - took(a); });' ' console.log(\"slowest step: \" + leaves[0].name + \", \" + took(leaves[0]) + \" ms\");' ' const priced = spans.filter(function (s) { return cost(s.attributes) > 0; });' ' priced.sort(function (a, b) { return cost(b.attributes) - cost(a.attributes); });' ' console.log(\"costliest step: \" + priced[0].name + \", \" + cost(priced[0].attributes) + \" units\");' ' for (const s of spans.filter(function (one) { return one.status === \"error\"; })) {' ' const up = spans.find(function (one) { return one.span_id === s.parent_span_id; });' ' console.log(\"failed: \" + s.name + \", inside \" + (up ? up.name : \"nothing\"));' ' }' >> trace2.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the agent trace, part 5
docker exec -w /home/node/project agent sh -c "printf '%s\n' ' const live = { trace_id: \"7a3f0c1d00000000000000000000aa02\", span_id: sid(7), parent_span_id: \"\",' ' name: \"model: live check\", start: 0, end: 600, status: \"ok\", attributes: {} };' ' const messages = [{ role: \"user\", content: \"In one short sentence, what does a span record?\" }];' ' const reply = await ask(messages, \"A span records one timed step of a request.\", 40);' ' live.attributes = { model: \"lab\", input_tokens: reply.inTokens, output_tokens: reply.outTokens, recorded: reply.recorded };' ' console.log(\"live span: \" + JSON.stringify(live));' ' console.log(\"model said: \" + reply.text);' '}' 'main();' >> trace2.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Run and read the trace
docker exec -w /home/node/project agent node trace2.jsShown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
What the Run prints
| Line | What it shows |
|---|---|
| trace 7a3f0c1d00000000000000000000aa01 | The trace id every span shares |
| tool: delivery date 2000 ms error | A tool span that failed |
| model: answer 1800 ms ok, fell back | A model span that used another model |
| slowest step: tool: delivery date, 2000 ms | The longest step with no children |
| costliest step: model: plan, 3600 units | Tokens times the price of its model |
| live span: {...} | One live call as a span. Its token counts are null when a recorded sample answers |
The cells students fill in are left blank in this preview.
Read a trace three ways
For speed, find the step with no children that took longest. For cost, multiply each model span's tokens by its model's prices.
For failures, list each span with an error status and the span it sits inside. A failed child inside a span that ended well means the agent recovered.
A common mistake
Warning
Many people think the slowest step is also the costliest. Here the delivery date tool is slowest, but the plan call costs most. Waiting makes time and tokens make cost, so check both before you change anything.
OpenTelemetry is an open standard for traces
OpenTelemetry is an open standard for traces, metrics and logs. Many tools read its span shape, so one record works with more than one store.
It also has draft names for the attributes of AI calls. The drafts are still changing, so treat the names below as an example. Check the current docs before you use one.
Draft names, check the current docs
| Our key | A draft name | What it holds |
|---|---|---|
| model | gen_ai.request.model | The model asked for |
| input_tokens | gen_ai.usage.input_tokens | Tokens sent in |
| output_tokens | gen_ai.usage.output_tokens | Tokens that came out |
| tool | gen_ai.tool.name | The tool called |
| none here | gen_ai.operation.name | The kind of call, such as chat |
The cells students fill in are left blank in this preview.