15.1 运行追踪
第 14 章让 minagent 能在出错时分类重试、超时取消、幂等地处理副作用。但一个会自我修复的 Agent，如果修不好、或者修得太慢，你几乎无从下手：一次 run 里模型调用了几轮、每轮各花多久、哪个工具是瓶颈、错误卡在哪一步——这些信息现在全散落在 print 里，靠肉眼一行行翻。要回答「慢在哪、错在哪」，先得让运行过程结构化。
本节把 minagent 推进到
minagent/tracing.py：定义Span(name, start, end, parent_id, attributes)，用 contextvar 维护父子关系，实现Tracer（start_span/end_span/export），把一次 run 变成一棵可打印、可导出的 span 树。
15.1.1 一次运行本来就是一棵树
很多人以为一次 Agent run 是「一串步骤」，其实它是一棵树。root 是一次 run；run 之下挂着若干模型调用（每轮 complete()）；每个模型调用之下，又挂着它那一轮触发的工具调用；13 章引入多 Agent 后，每个子 Agent 的执行本身又是一个带完整子树的节点。
| 层级 | 对应什么 | 典型数量 |
|---|---|---|
| root span | 用户的一次请求（一次 run） | 1 |
| 模型调用 span | 每轮 model.complete() | 1 ~ max_steps |
| 工具调用 span | 每次 registry.call() | 0 ~ N |
| 子 Agent span | supervisor 派发的 worker（13 章） | 0 ~ N |
为什么是树而不是列表？因为父子关系携带信息。同样一行「工具 search 耗时 800 ms」，如果不知道它挂在第 2 轮模型调用之下，你就不知道它是「第 2 轮才引入的慢」还是「一直慢」。列表丢掉了嵌套，树保住了嵌套——而排查问题时，嵌套往往就是答案本身。
用一个反例说明。假设一次 run 打印出这样一串扁平日志：
model.complete 1530ms
tool.search 12ms
model.complete 1490ms
tool.search 820ms
model.complete 1100ms
你只能看到「第二轮里有个 820 ms 的 search」。它为什么慢？是这一轮上下文变大了，还是这个 query 特别重？树里如果 root span 带 input 属性、每个 tool.search span 带 query 属性，答案立刻现形。扁平日志把时间顺序留下了，却把归属关系丢了。
15.1.2 Span：一个调用的记录单元
一个 span 就是「一段有名字、有起止、能挂属性的执行区间」。它是一棵树的节点：
# minagent/tracing.py
from __future__ import annotations
import time
import uuid
from dataclasses import dataclass, field
from typing import Any
@dataclass
class Span:
name: str
span_id: str
parent_id: str | None
start: float
end: float | None = None
attributes: dict[str, Any] = field(default_factory=dict)
children: list["Span"] = field(default_factory=list)
@property
def duration_ms(self) -> float:
if self.end is None:
return 0.0
return (self.end - self.start) * 1000.0
七个字段各有分工：
| 字段 | 类型 | 作用 |
|---|---|---|
name | str | 语义标签：run / model.complete / tool.search |
span_id | str | 自身身份，供父子引用 |
parent_id | str | None | 父节点身份；None 表示这是一棵树的根 |
start / end | float | 起止时刻，来自单调时钟 |
attributes | dict | 任意键值负载：step、query、stop_reason |
children | list[Span] | 子节点，便于就地渲染与遍历 |
start / end 用的是 time.perf_counter() 而不是 time.time()。这是一个必须踩对的坑：time.time() 是墙上时钟，会被系统对时（NTP）前后拉扯，两次调用之间可能出现负数时长；perf_counter() 是单调递增的，专为测时长设计。时长用单调时钟，时间点用墙上时钟，两者不要混用。
parent_id 存的是身份字符串而不是对象引用。这样导出成 JSON 后，父子关系依然成立——换成对象引用，序列化时要么循环、要么丢失。children 则是内存里的便利字段，让渲染不用二次查找。
15.1.3 Tracer：用 contextvar 维护父子关系
有了 span，下一个问题是：新开的 span 怎么知道「我的父亲是谁」。有两种做法：
| 做法 | 写法 | 代价 |
|---|---|---|
| 显式传参 | start_span("tool.search", parent=cur) | 每层都要把 cur 往下传，侵入业务代码 |
| contextvar | 读当前上下文里的 span | 零侵入，但依赖上下文传播规则 |
本节选 contextvar。它天然契合「函数调用栈」的嵌套语义：进入 with 块时把新 span 设为「当前」，退出时恢复「上一层」。这正是第 14 章 asyncio.TaskGroup 里每个并发任务互不干扰所需要的——每个任务有自己的上下文副本，span 不会串味。
# minagent/tracing.py
from contextlib import contextmanager
from contextvars import ContextVar, Token
from typing import Iterator
CURRENT_SPAN: ContextVar[Span | None] = ContextVar("current_span", default=None)
class Tracer:
def __init__(self) -> None:
self.spans: list[Span] = []
self._roots: list[Span] = []
self._tokens: dict[str, Token] = {}
def start_span(self, name: str, **attributes: Any) -> Span:
parent = CURRENT_SPAN.get()
span = Span(
name=name,
span_id=uuid.uuid4().hex[:8],
parent_id=parent.span_id if parent else None,
start=time.perf_counter(),
attributes=dict(attributes),
)
self.spans.append(span)
(parent.children if parent else self._roots).append(span)
self._tokens[span.span_id] = CURRENT_SPAN.set(span)
return span
def end_span(self, span: Span) -> None:
span.end = time.perf_counter()
CURRENT_SPAN.reset(self._tokens.pop(span.span_id))
逐条读：
parent = CURRENT_SPAN.get()：取出此刻上下文里的 span，它就是新 span 的父亲；为空则新 span 成为 root。(parent.children if parent else self._roots).append(span)：把自己挂到父亲的children，没有父亲就挂到_roots——这是「树」的成型动作。CURRENT_SPAN.set(span)：把自己设为「当前」，返回一个Token存起来，供退出时还原。end_span：填end、用Token把上下文还原成父亲。必须还原，否则兄弟 span 会错误地挂到前一个兄弟下面。
再包一层 @contextmanager 让调用处写成 with，兼顾正确与简洁：
@contextmanager
def span(self, name: str, **attributes: Any) -> Iterator[Span]:
s = self.start_span(name, **attributes)
try:
yield s
finally:
self.end_span(s)
finally 是关键：即使 with 块里抛异常，end_span 也一定执行，span 不会变成「永远没有 end」的半截记录。第 14 章的异常处理在这里得到了延续——出错的 span 同样要被记录，那恰恰是最该看的。
15.1.4 把追踪接进 run 循环
把 3.1 的朴素循环外面套上三层 span：root 一次、每轮模型调用一次、每次工具调用一次：
def traced_run(model, registry, user_input, tracer, max_steps=8):
with tracer.span("run", input=user_input) as root:
messages = [Message(role="user", content=user_input)]
for i in range(max_steps):
with tracer.span("model.complete", step=i) as ms:
resp = model.complete(messages, registry.schemas())
ms.attributes["stop_reason"] = resp.stop_reason
messages.append(resp.message)
if not resp.message.tool_calls:
root.attributes["final"] = resp.message.content
return resp.message.content
for tc in resp.message.tool_calls:
with tracer.span(f"tool.{tc.name}", step=i) as ts:
result = registry.call(tc)
ts.attributes["ok"] = "error" not in result
messages.append(Message(role="tool", content=result, tool_call_id=tc.id))
return ""
对比 3.1 的 run，业务逻辑一行没改，只是每个动作外面包了一层 with tracer.span(...)。这就是 contextvar 方案的收益：追踪是横切关注点，不该污染主流程。三处 span 名各有约定：root 叫 run、模型调用叫 model.complete、工具调用叫 tool.<名字>。命名统一后，下游系统就能靠名字前缀做过滤与聚合。
attributes 里塞的都是排查时要看的字段：root 记 input 与 final，模型调用记 step 与 stop_reason，工具调用记 ok。这些字段平时不占内存、不影响逻辑，一旦出事却是一手证据。
15.1.5 真跑：带两个工具调用的 run
构造一个两轮工具调用的 run：先 add(2,3)，再 mul(5,4)，最后给出答案。用假模型脚本驱动，真跑打印 span 树（Python 3.14.6）：
tracer = Tracer()
model = FakeModel([
[ToolCall(id="c1", name="add", arguments={"a": 2, "b": 3})],
[ToolCall(id="c2", name="mul", arguments={"a": 5, "b": 4})],
"结果是 20。",
])
registry = ToolRegistry()
registry.add(Tool("add", lambda a, b: json.dumps({"result": a + b})))
registry.add(Tool("mul", lambda a, b: json.dumps({"result": a * b})))
final = traced_run(model, registry, "先算 2+3，再乘 4", tracer)
print("最终回答:", final)
print()
print(tracer.render())
最终回答: 结果是 20。
run [4.21 ms] {'input': '先算 2+3，再乘 4', 'final': '结果是 20。'}
- model.complete [1.53 ms] {'step': 0, 'stop_reason': 'tool_use'}
- tool.add [0.02 ms] {'step': 0, 'ok': True}
- model.complete [1.49 ms] {'step': 1, 'stop_reason': 'tool_use'}
- tool.mul [0.02 ms] {'step': 1, 'ok': True}
- model.complete [1.05 ms] {'step': 2, 'stop_reason': 'end_turn'}
一棵六节点的树：1 个 root、3 次模型调用、2 次工具调用。缩进就是父子关系——两个 tool.* 各自挂在它那一轮的 model.complete 之下（虽然渲染里同层展开，parent_id 已把它记录在案）。三个可直接读出的结论：
- run 总耗时 4.21 ms，而三次模型调用合计约 4.07 ms——时间几乎全花在模型上，工具可以忽略。如果哪天 run 慢到几秒，这行对比立刻告诉你该优化哪边。
stop_reason按轮次变化：前两轮tool_use、末轮end_turn。这串值就是「Agent 为什么停下来」的完整轨迹，比一句「跑完了」信息量大得多。- 每个
tool.*的ok都是True。哪天某个工具返回了{"error": ...}，这里会翻成False——错在哪，一眼可见。
15.1.6 导出：把树交给下游系统
内存里的 Span 对象不能直接落盘或发给追踪后端，得先序列化。export() 把整片森林转成纯 dict 的嵌套列表：
def export(self) -> list[dict[str, Any]]:
return [self._to_dict(s) for s in self._roots]
def _to_dict(self, span: Span) -> dict[str, Any]:
return {
"name": span.name,
"span_id": span.span_id,
"parent_id": span.parent_id,
"duration_ms": round(span.duration_ms, 3),
"attributes": span.attributes,
"children": [self._to_dict(c) for c in span.children],
}
_to_dict 递归展开 children，得到的就是一棵 JSON 树。真跑导出前 520 个字符：
[
{
"name": "run",
"span_id": "73e6966b",
"parent_id": null,
"duration_ms": 4.206,
"attributes": {
"input": "先算 2+3，再乘 4",
"final": "结果是 20。"
},
"children": [
{
"name": "model.complete",
"span_id": "5e74442d",
"parent_id": "73e6966b",
"duration_ms": 1.529,
"attributes": {
"step": 0,
"stop_reason": "tool_use"
},
"children": []
},
JSON 形态和 render() 的缩进树是同一份数据、两种呈现：缩进树给人看，JSON 给机器看。render() 适合本地调试时直接 print；export() 适合写进文件、灌进 Jaeger/Tempo 这类追踪后端，或在测试里做断言。注意 parent_id 在 JSON 里是字符串、在 root 上是 null——这套格式与 OpenTelemetry 的 span 结构同构，将来接真实追踪后端时字段几乎能直接映射。
15.1.7 span 树的价值：慢在哪、错在哪
把这一节收成两个问题，看 span 树分别怎么答：
| 问题 | 扁平日志的困境 | span 树怎么答 |
|---|---|---|
| 慢在哪 | 只有一长串耗时，看不出谁属于谁 | 每层的 duration_ms 相加对比，定位瓶颈层 |
| 错在哪 | 错误行淹没在输出里 | 顺着 ok=False 的 span 上溯，直接找到出错分支 |
定位慢靠的是「分层求和」：root 的耗时约等于所有子 span 之和，哪个子树的占比高，瓶颈就在那。如果 model.complete 占了大头，是上下文太长（回到 6.2 裁剪）；如果某个 tool.* 占了大头，是这个工具的实现或它的下游慢。定位错靠的是「沿树上溯」：一个 ok=False 的工具 span，往上能看到它属于哪一轮、那一轮的 stop_reason 是什么、root 的 input 是什么——一次出错，上下文全在手边。
这也解释了为什么追踪（tracing）和普通日志是两种东西：日志是点（某时刻发生了某事），追踪是结构（这次运行由哪些部分组成、各部分耗时几何）。点适合回答「发生了什么」，结构适合回答「为什么是它、卡在哪」。两者互补，缺一不可——15.2 就会讲怎么把日志挂到这张结构上。
真实模型下会怎样：本节所有耗时都是假模型 time.sleep(0.001) 撑出来的，量级在毫秒，毫无参考价值。真实模型的单次调用通常是数百毫秒到数十秒，而且方差极大——同样的 prompt，早高峰和凌晨可能差一倍。这意味着真实 span 树上，model.complete 会稳定地占掉 90% 以上的时间，tool.* 反而常常是零头；真正的慢往往来自串行的轮数太多（每一轮都要等一次完整往返），而不是单次调用慢。所以真实系统里，span 树最常用来回答的是「这次 run 为什么要调 6 轮模型」——把 6 个 model.complete span 的 step 与 stop_reason 排开，就能看出循环是不是陷在「调工具—失败—再调」里空转。此外，真实追踪后端会用分布式 trace_id把跨服务的调用串成一张大图，本节的 span_id / parent_id 只是这张图的单机雏形。
阅读导航：上一节：14.3 幂等与副作用 · 下一节：15.2 结构化日志与关联 ID 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。