第 25 章 · 一次 run 到底跑了什么

上一章：24 · OS 级沙箱

---

这一章要解决的问题

第 04 章就加了"可观测性"：结构化日志、AgentStep、调试事件流。第 07 章又把整个会话落成 JSONL。到现在为止，一次 run 里发生的每件事都被记下来了。

然后你会遇到一个问题：记下来了，但答不出来。

一次 run 跑了 40 秒。哪一步慢？是模型在想，还是某个工具卡住了？如果它调了三次 grep，是三次都慢，还是有一次特别慢？如果它派了个子代理去做调研，子代理花的时间算谁的？

这些问题的答案全都在日志里。但要拼出来，你得把几百行 JSONL 按时间排一遍，人肉配对"这个 tool_started 对应哪个 tool_finished"，然后自己算减法。

这不是"缺数据"，是缺结构。

读完这一章，同一次 run 会长成这样——这是一次真实运行的真实数据，不是示意图：

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

主 agent 读完文件后派了子代理。子代理有自己的 context window、自己的会话文件， 但它的 span 落在父级 task 那根条里——因为它继承了父级的 trace id。 上面为了看清形状把子代理内部折叠了， 完整的 114 行在这里。

这一章做两件事：

1. 给已有的事件流补上 span 语义——起止时刻、父子嵌套——让"哪一步慢"变成一眼能看的东西。
2. 补上 subagent：第 23 章的差距表里，Subagent 那一行写的是"无"。这一章把它填上，顺便让它成为 trace 结构的第一个真正的考验——因为子代理跑在另一个会话文件里，链路必须跨文件接起来。

这一章不做什么

不引入任何观测厂商的 SDK。

这不是洁癖。第 05 节会讲清楚：你真正需要绑定的东西是语义约定，不是某个后端。绑错了层，换后端就要改主循环；绑对了层，换后端是改一个环境变量。

读完这一章，你能做到

1. 打开一次 run 的瀑布图，指着最长的那根条说"时间花在这儿"。
2. 一个子代理跑在独立的 context window 和独立的文件里，你仍然能看到它嵌在派生它的那次工具调用下面。
3. 把同一次 run 导进两个不同的开源观测后端，不改一行 harness 代码。
4. 断网、不装任何后端，照样能看完整链路——因为数据一直在你自己的文件里。

小节

#	小节	讲什么
01	答不出来的那个问题	日志齐全，但"哪一步慢"要人肉拼
02	事件流不等于 trace	差的是起止和嵌套，不是数据量
03	两张图，不是一张	消息血缘和 span 树是正交的，都得留
04	子代理跑在别的文件里	跨文件的父子关系靠什么接
05	不绑厂商的出口	该绑的是语义约定，不是后端
06	这一章花了多少钱	依赖账、实测踩的坑、还差什么

动手之前

确认测试全绿：

npm test

从 01 · 答不出来的那个问题 开始。