Find the slow step
Tracing an LLM call means recording what each step of a request did and how long it took. It matters because a model feature fails in the middle of a chain, and a log line at each end cannot say where.
A user reports that answers take ten seconds. Was it the prompt, the model, a retry or the check afterwards? A trace answers that in one look.
By the end of this lesson
Note
I can record what each call did, so that I can find where a failure or a delay came from.
Key words
| Word | What it means |
|---|---|
| Trace | the record of one request from start to end |
| Span | one timed step inside a trace |
| Parent | the span that contains another span |
| Attribute | a named fact stored on a span |
| Trace id | the one id every span of a request shares |
| Redaction | removing secrets before a record is stored |
The cells students fill in are left blank in this preview.
A trace is a tree of spans
A trace is one request. It is made of spans. Each span has a name, a start, an end and a parent: the span that contains it. One span has no parent. It is the root.
Every span of a request carries the same trace id. That is how a store puts them back together. A span also holds attributes, such as the route or the outcome.
Worked example: one request
| Span | Parent | Start | End | Took |
|---|---|---|---|---|
| request | none | 0 | 856 | 856 ms |
| build prompt | request | 0 | 4 | 4 ms |
| model call | request | 4 | 854 | 850 ms |
| check reply | request | 854 | 856 | 2 ms |
The cells students fill in are left blank in this preview.
What a trace must never hold
A trace store is read by many people and kept for weeks. So a span never holds a secret: an API key, a token or a password. It never holds personal data: an email address, a name or a phone number.
It usually should not hold the prompt or the reply either. Store sizes, counts and outcomes. Remove the dangerous keys in one place, before the span is saved. That step is called redaction.
A common mistake
Warning
Many people think logging the full prompt is harmless because the log is internal. Prompts hold what users typed, and users type names and secrets. Log the length and the outcome, and keep the text out.
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 tracer, part 1
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'const { ask } = require(\"./model\");' '' 'let now = 0; // a clock we move ourselves, so every run prints the same times' 'const spans = [];' 'function tick(ms) { now = now + ms; }' 'function start(name, parent) {' ' const span = { id: spans.length + 1, name, parent, start: now, end: now, attrs: {} };' ' spans.push(span);' ' return span;' '}' 'function finish(span) { span.end = now; }' > trace1.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the tracer, part 2
docker exec -w /home/node/project agent sh -c "printf '%s\n' '// Keys that must never reach a trace store: secrets and personal data.' 'const NEVER = [\"email\", \"api_key\", \"prompt\", \"name\"];' 'function note(span, key, value) {' ' span.attrs[key] = NEVER.includes(key) ? \"[dropped]\" : value;' '}' >> trace1.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the tracer, part 3
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'function show(parent, depth) {' ' for (const s of spans) {' ' if (s.parent === parent) {' ' console.log(\" \".repeat(depth) + s.name + \" \" + (s.end - s.start) + \" ms \" + JSON.stringify(s.attrs));' ' show(s.id, depth + 1);' ' }' ' }' '}' >> trace1.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Write the tracer, part 4
docker exec -w /home/node/project agent sh -c "printf '%s\n' 'async function main() {' ' const root = start(\"request\", 0);' ' note(root, \"route\", \"/ask\");' ' note(root, \"email\", \"[email protected]\");' ' const build = start(\"build prompt\", root.id);' ' tick(4); finish(build);' ' const call = start(\"model call\", root.id);' ' const messages = [{ role: \"user\", content: \"Name one use of a trace, in one sentence.\" }];' ' const reply = await ask(messages, \"A trace shows which step of a request was slow.\", 40);' ' tick(850); // a fixed 850 ms on our clock, whatever the real call took' ' note(call, \"outcome\", reply.text.length > 0 ? \"ok\" : \"empty\");' ' note(call, \"prompt\", messages[0].content);' ' finish(call);' ' const check = start(\"check reply\", root.id);' ' tick(2); finish(check); finish(root);' ' console.log(\"trace t-0001\");' ' show(0, 0);' '}' 'main();' >> trace1.js"Shown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
Run and print the trace
docker exec -w /home/node/project agent node trace1.jsShown here, not run. Create a free account to press Run and type it into your own lab’s terminal.
A stand-in trace, and how to read it
The lab has no tracing service, so the spans live in a list and the clock is a number the script moves. A real system sends spans to a tracing service and reads the real clock. The shape is the same.
To find the slow step, use self time: a span's duration minus the durations of its children. A parent always looks slow, because it contains its children.
One possible output
| Line | What it shows |
|---|---|
| trace t-0001 | The trace id |
| request 856 ms | The root, with the route and the email dropped |
| build prompt 4 ms | A child, two spaces in |
| model call 850 ms | The slow step, with the prompt dropped |
| check reply 2 ms | The last child |
The cells students fill in are left blank in this preview.