Skip to content

Chapter 25 · What Actually Happened During That Run

Previous: 24 · OS-level sandbox


The problem this chapter solves

Observability arrived back in Chapter 04: structured logs, AgentStep, a debug event stream. Chapter 07 persisted whole sessions to JSONL. By now, everything that happens during a run is written down.

Then you hit this: it is written down, and you still cannot answer the question.

A run took 40 seconds. Which step was slow? Was the model thinking, or did a tool hang? If it called grep three times, were all three slow or just one? If it delegated research to a subagent, whose time was that?

Every answer is in the log. But to assemble one you have to sort a few hundred JSONL lines by time, pair up "which tool_finished belongs to which tool_started" by hand, and do the subtraction yourself.

That is not missing data. It is missing structure.

By the end of this chapter the same run looks like this — real data from a real run, not a mock-up:

114 spans · 559.60s · deepseek-v4-flash
runagent run
559.60s
modelchat deepseek-v4-flash
2.44s
toolfind
30ms
toolfind
26ms
modelchat deepseek-v4-flash
1.89s
toolls
10ms
toolread
34ms
modelchat deepseek-v4-flash
8.74s
toolls
20ms
tooltask
90.41s
subagentsubagent ↓ 10×model 49×tool
78.38s
modelchat deepseek-v4-flash
16.93s
toolread
50ms
tooltask
112.41s
subagentsubagent ↓ 9×model 15×tool
45.12s
modelchat deepseek-v4-flash
9.33s
toolls
6ms
toolread
3ms
tooltask
61.67s
modelchat deepseek-v4-flash
14.75s
toolread
21ms
toolread
12ms
toolgrep
277ms
modelchat deepseek-v4-flash
12.84s
toolread
6ms
toolread
9ms
toolread
7ms
toolls
3ms
toolfind
11ms
modelchat deepseek-v4-flash
8.62s
tooltask
76.33s

The main agent read a file, then delegated to a subagent. That subagent has its own context window and its own session file, yet its spans sit inside the parent's task bar — because it inherited the parent's trace id. The subagent's interior is folded here so the shape stays visible; all 114 rows are here.

This chapter does two things:

  1. Adds span semantics to the existing event stream — start and end, parent and child — so "which step was slow" becomes something you can see.
  2. Adds subagents. Chapter 23's gap map lists Subagent as none. This chapter fills it in, and in doing so gives the trace structure its first real test: a subagent runs in a different session file, so the chain has to survive crossing a file boundary.

What this chapter does not do

It does not pull in an observability vendor's SDK.

Not out of purism. Section 05 makes the case: the thing worth binding to is the semantic convention, not a backend. Bind at the wrong layer and switching backends means editing the sampling loop. Bind at the right one and switching backends is an environment variable.

After this chapter you can

  1. Open a run's waterfall and point at the longest bar.
  2. See a subagent — running in its own context window and its own file — nested under the tool call that spawned it.
  3. Send the same run to two different open-source backends without touching a line of harness code.
  4. Read the whole chain offline, with no backend installed, because the data was always in your own files.

Sections

#SectionAbout
01The question you cannot answerComplete logs, and "which step was slow" is still manual
02An event stream is not a traceWhat is missing is identity and parentage, not volume
03Two graphs, not oneMessage lineage and the span tree are orthogonal; keep both
04The subagent runs in another fileWhat holds a parent/child link across files
05An exit that binds no vendorBind the convention, not the backend
06What this chapter costDependency budget, what broke, what is still missing

Before you start

Confirm the suite is green:

bash
npm test

Start with 01 · The question you cannot answer.