10 可观测性：trace、日志、指标、回放

第 9 章把质量变成了可比较的数字：准确率的区间、配对差值的显著性、成本与尾延迟。但数字只回答「这一批怎么样」，不回答「这一次为什么失败」。当一条 run 从 71% 的成功率里掉出去，你手上只有一个最终答案和几万行日志；没有轨迹，就只能靠猜。可观测性就是把「这一次」变成可检查的证据：它既服务于排障，也服务于评估集的样本回捞、事故审计与回归复现。

先说结论：agent 的可观测性以 trace 为主干；日志解释单步，指标回答趋势，回放负责复现。 三者的关系不是三个并列的管道，而是一棵树、树上的注释、树的聚合统计，以及把树重新走一遍的能力。传统微服务也讲这三件事，但 agent 的 trace 多出四类记录：模型调用（模型、token、结束原因）、工具调用（参数摘要、副作用、幂等键）、预算变化（步数、token、金额的余额）、决策理由摘要（为什么选这个动作，一句话，不是完整思维链）。缺了这四类，trace 只是一条 HTTP 调用链，解释不了 agent 的行为。

这一章处在全书的证据层。第 9 章的评估依赖 trace 做轨迹级评分；第 11 章的安全事件要靠 trace 还原「哪段不可信内容在什么时候获得了执行权」；第 12 章的审计要把审批、权限与数据访问写成不可篡改的证据。三者共用同一套字段与同一套关联 id，所以这一章先把数据模型钉死，再谈工具。实验 experiments/ch10/ 用 11 个 span 把模型、工具、守卫、审批、断链、时钟漂移与 TZ 全部做成可运行、可复现的输出。

读图：横轴是时间，纵轴是调用栈。最长的单个 span 不是根，而是 tool #2（约 0.61 s），紧随其后是 llm #2（约 0.52 s）；guard 只占 0.09 s，却做出了拒绝出口的决定。把同类相加，三段 LLM 共 1.41 s（56%），两段工具共 0.87 s（35%），guard 与调度合计 9%。这解释了为什么「优化模型」最多只能拿回一半：另外 35% 在工具，9% 在守卫与调度；也解释了为什么只看总成功率，会把一次 guard 拒绝误判成模型能力问题。

10.1 三支柱在 agent 里的变化：trace 为主干

先看一个具体的排障场景。某客服 agent 的周成功率从 71% 掉到 68%，P95 延迟从 2.1 s 涨到 3.4 s，成本涨了 12%。指标能告诉你三件事同时变差，但给不出原因。打开一条失败 run 的 trace，看到的是：第 2 步的 kb.search 重试了两次（第一次 ETIMEDOUT），第 3 步的模型输入从 1.2k token 涨到 4.1k（重试把两段检索结果都塞进了上下文），第 4 步的 guard 因为预算不足拒绝了写工单，最终以 budget_exhausted 结束。三个指标同时变差，根因是一个工具的瞬时超时加上一次不必要的结果累积；修法是重试时替换而不是追加检索结果，并把超时预算单独记账。

这个因果链只能由 trace 给出。日志里有三条 WARN tool.retry，但没有「它导致上下文膨胀」这条边；指标里有成功率与成本，但没有「哪一步」；把日志按时间戳排序能猜出顺序，却猜不出父子关系——尤其当重试与并行工具同时发生时，时间戳只能给出偏序。

这张表说明什么：三根支柱不是「同一份数据的三种视图」，而是三种不同的证据。日志是句子，指标是报表，trace 是账本。账本可以生成报表，报表不能反推账本；句子可以给账本加注，但不能替代账本。把三者混在一个日志管道里，最常见的后果是「日志很全，但没人能回答第 3 步为什么改了参数」。三者的保留策略也不该共用一个开关：例如 trace 按周、日志按天、指标按月，审计证据则按合规周期。

1.8 节给过最小版本的 step 记录；这一章把它扩成完整的 span 模型。agent 的 trace 比微服务多出的四类记录，各自有最小字段集：

这张表说明什么：四类记录里，只有「决策摘要」是 agent 特有的语义字段，另外三类是把已有动作提升为一等公民。很多团队把工具调用写成日志、把 token 算进账单、把预算放在内存里，结果 trace 上只有模型的父子关系，排障时仍要回到日志里拼图。

这个定义故意把「采样标记」放进属性。采样不是查询时的一个参数，而是写入时的决定：一条 run 要么被完整记录，要么从一开始就不记录。若在 span 级各自决定，父子关系会出现「父被采、子没采」的洞，trace 直接断链。W3C Trace Context 的 traceparent 里有一个 sampled 标志位，就是为这件事准备的（10.2 节）。

                     ┌──────────────────────────────────────────────┐
                     │              metrics（投影，按窗口聚合）       │
                     │  成功率 · 终止原因 · 步数 P50/P95/P99 · 成本   │
                     └──────────────▲───────────────────────────────┘
                                    │ group by (task, model, tool, status)
                                    │
   logs（注释）                     │                    replay（重走）
   ┌──────────────┐        ┌────────┴─────────┐        ┌────────────────┐
   │ WARN retry   │───────▶│  trace（主干）    │───────▶│ 记录输入/结果   │
   │ INFO decision│ trace_id│ run              │        │ 不执行副作用    │
   │ ERROR egress │ span_id │  └ step          │        │ 差分对比        │
   └──────────────┘        │     ├ llm        │        └────────────────┘
                           │     ├ tool       │
                           │     ├ guard      │
                           │     └ approval   │
                           └──────────────────┘
                              ▲            │
                              │            ▼
                        span link      attributes（semconv + 成本 + 版本）

读图：三根支柱围绕 trace 组织，而不是并排。日志挂在 span 上（同一个 trace_id/span_id），指标从 span 聚合出来（同一套 kind/status/name 维度），回放读的是 span 上的输入输出引用。箭头方向很重要：trace 可以生成指标与回放，指标不能反推 trace；这也解释了为什么「先把日志接上，以后再补 trace」通常补不起来——日志里没有 parent_span_id，事后无法重建调用栈。

排障时不要从「把所有数据都查一遍」开始。不同问题对应不同的入口：

这张表说明什么：入口选错，会在错误的数据里挖很久。成本问题从日志入手，会看到一堆无关的重试；安全问题从 trace 的 status 入手，会漏掉「业务成功但数据被带出」的路径。先确定问题属于哪一类，再决定打开哪根支柱。

观测数据本身也有成本。按 11 个 span、每个 1 KB 估，100 万次 run 约 11 GB/天；加上日志与内容副本，很容易到百 GB 级。这不是「少记」的理由，而是「分层记」的理由：元数据全采、内容采样、失败全留（10.4.3）。把成本算清楚，采样策略才有依据，而不是等到账单来了再删字段。

10.2 trace 模型：run、step、tool、llm span

一个 span 是一次有名字、有起止、有状态的操作。它不需要覆盖整个函数，也不应该细到每一行；划分标准是「排障时你会不会单独问它耗时/失败/参数」。对 agent，够用的层级是三层：run → step → 叶子操作，叶子再分 llm、tool、guard、approval 四种：

trace b27bc688…  （一次 run）
└─ run  invoke_agent support                       [0ms ................ +1985ms]  ok
   ├─ step 1  step                                 [ +0ms ....... +420ms]  ok
   │  └─ llm  chat gpt-4.1-mini                    [ +0ms ....... +420ms]  ok
   │        gen_ai.usage.input_tokens=820  output_tokens=64  finish=tool_calls
   ├─ step 2  step                                 [+420ms ....... +300ms]  ok
   │  └─ tool  execute_tool kb.search              [ +0ms ....... +300ms]  ok
   │        attempt=2  retry event at +120ms  side_effect=read
   ├─ step 3  step                                 [+720ms ..... +1265ms]  ok
   │  ├─ llm  chat gpt-4.1-mini                    [ +0ms ....... +610ms]  ok
   │  ├─ guard  guard budget                       [+610ms ......... +5ms]  ok  decision=allow
   │  ├─ approval  approval ticket.write            [+615ms ........ +30ms]  ok  approved
   │  ├─ tool  execute_tool ticket.update          [+645ms ....... +240ms]  ok
   │  │        idempotency_key=idem-7f3a91  side_effect=write
   │  └─ llm  chat gpt-4.1-mini                    [+885ms ....... +380ms]  ok  finish=stop
   │
   └─ link ──▶ trace d4edfeea…  async job: notify.send  （另一个 trace，不是子 span）

读图：缩进是 parent 关系，方括号是相对父 span 的偏移与时长。guard 与 approval 是 step 的兄弟，不是 tool 的子节点——它们是对动作的决策，与动作本身并列；如果把审批塞进工具内部，你就无法区分「工具慢」与「等审批慢」。底部的 link 指向另一条 trace：异步投递任务在 run 结束后才开始，它有自己的根，用 link 指回发起它的 run。把 link 画成父子会伪造时间包含关系，waterfall 立刻出现负值（10.7 节）。

span 的字段不多，但每个都有排障用途：

这张表说明什么：trace_id/span_id/parent_span_id 是结构，name/kind 是索引，attributes/events 是内容。结构字段缺失无法事后补；内容字段可以在采集端裁剪。所以采集器的第一优先级是把结构写对，而不是把 payload 记全。

一条真实的 tool span 记录（来自本章实验，省略了部分字段）：

{
  "type": "span",
  "trace_id": "b27bc6882af7fd2aab0df67da4c969f3",
  "span_id": "0eaef9545f17ea50",
  "parent_span_id": "cc8c52bde4c0e1dc",
  "name": "execute_tool kb.search",
  "kind": "tool",
  "start": "2026-10-19T09:00:00.420+00:00",
  "end": "2026-10-19T09:00:00.720+00:00",
  "duration_ms": 300.0,
  "status": "ok",
  "attributes": {
    "gen_ai.operation.name": "execute_tool",
    "gen_ai.tool.name": "kb.search",
    "gen_ai.tool.call.id": "call_01",
    "gen_ai.tool.type": "extension",
    "mcp.method": "tools/call",
    "mcp.request.meta.traceparent": "00-b27bc6882af7fd2aab0df67da4c969f3-0eaef9545f17ea50-01",
    "app.tool.side_effect": "read",
    "app.tool.ok": true,
    "app.tool.attempts": 2,
    "app.tool.result": {"hits": 3, "top": "billing-refund-sla"}
  },
  "events": [
    {"name": "retry", "at": "2026-10-19T09:00:00.540+00:00",
     "attributes": {"attempt": 1, "error.type": "ETIMEDOUT"}}
  ]
}

注意三处设计。第一，status 是 ok：工具最终成功了，重试是过程，不是错误；错误率要按「第一次尝试是否失败」另算，否则重试会把首次失败掩盖掉。第二，app.tool.result 只放摘要，完整结果在受控存储里，按 span_id 回查。第三，mcp.request.meta.traceparent 记录发给 MCP server 的上下文头——这是跨进程传播的证据，不是装饰。

10.2.1 W3C Trace Context：traceparent 与 tracestate

跨进程传播用 W3C Trace Context。请求头 traceparent 的格式是：

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             │  │                                │                │
             │  │                                │                └─ flags：01 = sampled
             │  │                                └─ parent-id：调用方的 span-id（16 hex）
             │  └─ trace-id：32 hex，全零非法
             └─ version：00

接收方用这个 header 创建子 span：trace_id 原样继承，parent_span_id 取 header 里的 parent-id，自己的 span_id 新生成。tracestate 是可选的厂商状态，格式是逗号分隔的 key=value，规范上限 32 个 list-member；它适合放「采样优先级」「租户路由」这类需要跨厂商传递的少量状态，不适合放业务数据。

三个实现细节经常出错：

1. 全零 id 非法。 trace_id 全零或 span_id 全零必须拒绝，否则所有请求会被并到同一条 trace 上。
2. 版本号要宽容。 收到 01-... 时，若高位版本可解析，应按前缀解析并忽略未知尾部；直接拒绝会让升级期的链路断开。
3. sampled 标志只做「建议」。 下游可以升级采样（例如发现错误时强制记录），但不能把已采样的父 span 变成不采样，否则父子不一致。

MCP 在 params._meta 里传同样的字段。2026-07-28 版规范把这组键写进了文档：traceparent、tracestate、baggage 遵循 W3C 的值格式，并且作为 _meta 键名规则的一个例外，不加 DNS 前缀（加了 io.modelcontextprotocol.traceparent 之类的名字，反而会打断已有实现的链路）。客户端在 tools/call 里带上，server 应以它为父继续这条 trace；如果 server 无法继续（例如内部是批处理），就新建 trace 并用 link 指回，而不是丢掉上下文。一个请求体长这样：

{
  "jsonrpc": "2.0",
  "id": 42,
  "method": "tools/call",
  "params": {
    "name": "kb.search",
    "arguments": {"query": "退款 到账 时效"},
    "_meta": {
      "traceparent": "00-b27bc6882af7fd2aab0df67da4c969f3-0eaef9545f17ea50-01",
      "tracestate": "acme=s:2"
    }
  }
}

baggage 要慎用：它会在每一跳原样转发，很多人把 user_id、tenant、甚至邮箱塞进去，等于让 PII 沿着调用链扩散。baggage 只放路由与采样所需的非敏感键，且要有大小上限。

10.2.2 kind、status 与 events：别把业务失败当系统故障

kind 在 OTel 里有 internal/client/server/producer/consumer 五种。agent 的映射建议是：

只记一个 span 时按执行层记 internal；把传输与执行合成一个 client span，会让「网络超时」与「工具执行超时」混在同一个耗时里。

status 只有 unset/ok/error 三态。建议的判定规则是：操作本身失败（异常、超时、传输错误、5xx）才置 error；业务结果是否成功写进属性（app.tool.ok、app.decision.accepted）。理由很直接：如果 EINVAL（参数不合法，模型可以自我纠正）也标 error，工具错误率会随模型试错次数上升，而这个指标本来用于发现系统问题。两者混在一起，告警会失真。

这个定理的工程价值是给出了两个最便宜的体检指标：根数与孤儿数。一条正常的 run 只有一个根；根数变成 2，要么真的有两个入口（应该用 link 而不是共享 trace），要么有一个 span 丢了 parent。实验里的断链属于后一种成因，但表现形式是拆成了两条 trace：每条 trace 的根数各为 1，合起来 traces=2；第二条 trace 的根是一个 execute_tool，没有 run 也没有 link（10.7.1）。

10.3 属性：OTel GenAI/MCP 语义约定与成本

属性是 trace 的 schema。字段名一旦散开，后面所有 dashboard、告警、成本核算都要跟着改；更糟的是，同一个含义出现三个名字（model、model_name、llm.model），聚合时谁也说不清漏了哪一批。OpenTelemetry 的 GenAI 语义约定就是为此存在的：它规定模型调用、工具执行、agent 调用的属性名与 span 名。

本章以 semconv 1.44.0 为基线。这个基线里 GenAI 部分仍标为演进中，字段会改名或增补，所以工程上要做两件事：把语义约定版本写进资源属性（例如 app.semconv.version=1.44.0）；在采集端做一层字段映射，而不是让业务代码直接拼属性名。

这张表说明什么：前四行决定「谁在什么模型上做了什么」，中间四行决定「花了多少」，后六行决定「哪个工具/角色/会话」。一个都不应该缺，但也都不应该无限扩张——gen_ai.tool.name 的基数由工具数量决定，gen_ai.conversation.id 的基数由会话数量决定，后者绝不能进指标标签（10.5 节）。

span 名的约定是「操作 + 对象」：chat {model}、execute_tool {tool.name}、invoke_agent {agent.name}。名字要稳定、低基数；不要把参数拼进去（execute_tool kb.search(query=退款) 会让每个查询变成一个新 span 名），参数放属性或事件。

10.3.1 成本：token 乘单价，单价要带版本

成本不是语义约定的一部分，但没有它，可观测性回答不了「这次运行值不值」。最小实现是一张价目表加一个公式：

$$c_{\text{run}} = \sum_{i \in \text{llm}} \left( n^{\text{in}}_i , p^{\text{in}}_{m_i} + n^{\text{out}}_i , p^{\text{out}}_{m_i} \right) + \sum_{j \in \text{tool}} c_j$$

其中 $n^{\text{in}}_i, n^{\text{out}}_i$ 是第 $i$ 次模型调用的输入/输出 token，$p_{m_i}$ 是模型 $m_i$ 的单价（每 token），$c_j$ 是工具调用可能产生的费用（检索、外部 API）。注意口径：gen_ai.usage.input_tokens 已经包含缓存命中的 token，缓存读取量记在 gen_ai.usage.cache_read.input_tokens 里，它是前者的子集。计费时要把这部分按缓存价拆出来，不能既算全价又加一遍缓存量。

三个工程细节：

1. 单价表要版本化。 属性里写 app.cost.price_version，例如 demo-2026-10；价格变了，历史 run 的成本不能被重算成新价。报表要按「当时价格」还是「当前价格」重算，是一个显式选项，不是隐式行为。
2. 用整数微美元。 浮点美元累加会出现 0.30000000000000004；用 micro-USD 存整数，展示时再除。实验里 3 次调用共 1826 micros，等于 $0.001826，可以手算核对。
3. 报「每次成功」的成本。 单次成本会奖励「便宜但答错」；cost_per_success = total_cost / successes 才能和成功率一起看。9.6 节讲过，成本与质量要放在同一张帕累托图上。

成本要在 span 结束时算一次、写进属性，而不是查询时按当前价目重算。查询时重算会让历史成本随价格调整而漂移，也会让「上周那次为什么贵」变成一道无法复现的算术题。采集端算一次，报表只做求和与除法；价格表更新后，新旧 run 各自带自己的 price_version，比较前先对齐版本。

10.3.2 prompt 不进属性：用引用与哈希

最常见的错误是把 prompt 与 completion 全文塞进 span 属性。后果有三层：体积（一条 8k token 的 prompt 变成几十 KB 属性）、基数（属性值几乎唯一，索引爆炸）、合规（PII、密钥、用户内容进入一个访问控制更弱的系统）。正确做法是分层：

这张表说明什么：trace 存「指针与指纹」，内容存「受控副本」。两者用同一个 span_id 关联。这样既能回答「两次运行的 prompt 是否相同」，又不会把 trace 变成一个不受管的文本库。OpenTelemetry 也提供 gen_ai.input.messages/gen_ai.output.messages 这类记录完整消息的属性，但它们是 opt-in 且带隐私风险；默认应关闭，只在隔离的调试环境里打开。

属性与事件的分工也值得单独说。属性是「这个 span 的最终值」，事件是「span 内部的一次时刻」：

把重试写成属性，会丢掉每次尝试的时间与错误码；把 token 写成事件，会让每次聚合都要扫事件列表。判断标准是：这个值会不会被按 span 聚合。会，就放属性；只是某一刻发生过，就放事件。

这个定义的第二段把「指标标签」和「span 属性」分开：span 属性可以有一些高基数字段（例如 app.prompt.hash），因为 trace 后端按 trace_id 存储与检索；指标标签不行，标签组合数会乘到爆炸。很多系统把两者用同一套字段白名单，结果要么指标基数失控，要么 trace 缺字段。

10.4 日志：结构化、脱敏、采样与关联 id

日志在 agent 里最容易走向两个极端：要么只记「start/end」这种框架日志，排障时什么也回答不了；要么把模型输入输出、工具参数、HTTP 头全部打出来，制造一个又贵又危险的文本库。有用的日志既不是全量，也不是框架噪声，而是对一次决策的解释：为什么重试、为什么拒绝、为什么降级、为什么这条参数没通过校验。

一条来自本章实验的日志：

{
  "type": "log",
  "ts": "2026-10-19T09:00:00.540+00:00",
  "level": "WARN",
  "event": "tool.retry",
  "run_id": "support-refund",
  "trace_id": "b27bc6882af7fd2aab0df67da4c969f3",
  "span_id": "0eaef9545f17ea50",
  "fields": {"tool": "kb.search", "attempt": 1, "error": "ETIMEDOUT"}
}

三个细节值得注意。第一，span_id 是工具 span 的 id，不是 step 的：点开日志就能跳到那次重试，而不是跳到整个步骤。第二，fields 是结构化的，jq 能按 fields.error 分组；如果写成 "kb.search retry 1 ETIMEDOUT"，机器只能正则。第三，trace_id 与 run_id 同时存在：trace_id 用于技术排障，run_id 用于产品侧「这次会话发生了什么」，两者生命周期不同。

日志字段的最小集合：

这张表说明什么：日志的「结构」不是 JSON 本身，而是稳定的字段名与受控的值域。同样是 JSON，{"msg": "retry failed: ETIMEDOUT"} 仍然不可聚合；{"event":"tool.retry","fields":{"error":"ETIMEDOUT"}} 才能按错误码做趋势。

级别要按「行动」定义，而不是按严重程度：

WARN 与 ERROR 的差别不是「错误大小」，而是「系统是否已经无法自行恢复」。重试成功是 WARN（系统自愈了，但值得知道）；出口被策略拒绝是 ERROR（需要人确认是误杀还是攻击）。把重试标成 ERROR，告警会被正常的网络抖动淹没；把策略拒绝标成 WARN，安全事件会被埋在噪声里。

10.4.1 关联 id：从上下文注入，不要手填

日志与 trace 的关联只有一种可靠做法：从当前 span 上下文自动注入。手填 trace_id 的参数会漏、会错、会在异步边界丢失；一旦丢失，日志就退化成孤立的句子。本章实验里 Tracer.log() 直接从 contextvars 取当前 span：

def log(self, level: str, event: str, **fields: Any) -> None:
    ctx = _current.get()
    self.logs.append({
        "type": "log",
        "ts": iso_ns(self.clock.now_ns()),
        "level": level,
        "event": event,
        "run_id": self.run_id,
        "trace_id": ctx.trace_id if ctx else "",
        "span_id": ctx.span_id if ctx else "",
        "fields": fields,
    })

ctx 为空时写空串，而不是新生成一个 id——后者会制造一条看起来合法、实际对不上的假关联。空串要能被监控：unlinked_logs_total 持续大于 0，说明有代码路径在 span 之外打日志，或者异步边界没传上下文（10.7.1 的断链在日志侧的同款症状）。

run_id 与 trace_id 不要合并。一次用户任务可能因为重试、人工接管或异步续跑产生多条 trace；run_id 把它们串起来，trace_id 只表示一次执行。反过来，多 agent 协作时一条 trace 里可能有多个 agent.name，用 gen_ai.conversation.id 串会话，而不是复用 run_id。

10.4.2 脱敏：在写入前做，按白名单做

脱敏放在查询时做，等于没做：一个 SELECT *、一次导出、一个调试接口就能绕过。正确位置是日志写入前，且按白名单：只允许 schema 里声明的字段落盘，未知字段直接丢弃，而不是序列化整个对象。

这张表说明什么：脱敏的粒度是字段，不是「整条日志」。一条日志里可能同时有可记录的 tool、attempt 和不可记录的 args.headers.Authorization；按整条丢弃会失去排障信息，按整条保留会泄露。白名单 schema 让每个字段的处置显式，且新增字段必须经过一次评审。

一个可执行的验证手段是金丝雀：在测试环境注入一个已知的假密钥与假邮箱，跑完整流程后 grep 全部日志出口（文件、stdout、采集端缓冲），断言它们不出现。脱敏代码的单测只能证明函数行为，金丝雀才能证明「没有别的路径把它打出去」。

10.4.3 采样：失败全采，成功抽样，按 run 决策

日志量通常与步数成正比：一次 30 步的 run 产生几十条 INFO，加上工具与模型适配器的 DEBUG，很容易到几百条。全量保留的成本不只是存储，还有索引、查询延迟与脱敏审计的表面。

采样策略分两层：

• 头部采样：在 run 入口按 trace_id 哈希决定是否记录，采样标志随上下文传播。优点是实现简单、父子一致；缺点是无法预知这次会不会失败。
• 尾部采样：先把 span/日志缓冲在一个时间窗内，等 run 结束后按规则决定保留：失败全留、超过 P99 的慢 run 全留、其余按概率 $p$ 留。缺点是需要缓冲与集中式 collector。

一个够用的尾部策略是：

keep = (status == error)
    or (stop_reason in {max_steps, no_progress, budget_exhausted})
    or (duration_ms > p99_threshold)
    or (hash(trace_id) % 100 < 5)          # 5% 的成功样本

保留量的期望可以估：

$$V = N\left(\alpha + (1-\alpha),p\right)$$

其中 $N$ 是 run 数，$\alpha$ 是失败率，$p$ 是成功采样率。$N=10^6$、$\alpha=0.03$、$p=0.05$ 时约保留 78,500 条 run——足够做失败分析与趋势，又不至于把存储翻十倍。

两个容易忽略的约束：

1. 采样决策要按 run 统一。 同一 run 的 span、日志、内容副本要么都留，要么都不留；否则会出现「trace 有、日志没有」或「日志有、原文没有」的半套证据。采样标志应写进 traceparent 的 flags，并在内容存储的 key 上体现。
2. 用采样日志算指标要重加权。 如果失败全采、成功只采 5%，直接用日志算成功率会得到严重高估的结果。指标应从完整的计数器/直方图来，或对样本按 $1/p$ 加权；更好的做法是指标与采样解耦——指标只依赖计数，不依赖是否保留了明细。

反过来，只有章节没有句子，细节也不够：「超时」可能是工具慢、可能是审批没回来、可能是流式输出卡住，trace 只告诉你哪一段长，日志才告诉你那一段里发生了什么。

10.4.4 保留期：按证据价值分层，而不是一刀切

日志的保留期经常被设成一个全局值（例如「全部 30 天」），结果是两类数据同时受损：排障需要的明细被删得太早，审计需要的证据又被普通日志的噪声淹没。可执行的起点是按证据价值分层：

这张表说明什么：保留期不是存储成本问题，而是证据生命周期问题。热存支持「现在查」，温存支持「这个季度对比」，冷存支持「事故追责与合规」。三者用同一套删除流程，但保留时长与访问权限不同；把审批记录和 INFO 日志设成同一个 TTL，等于让审计证据随普通日志一起消失。

删除要能传播到每一层（6.6 节的墓碑机制同样适用）：热存删了、冷存还在，或者内容副本删了、回放包还在，都会让「已删除」的承诺失效。保留期的每个桶都要有 owner、到期任务与验证方式，而不是一个写在文档里的数字。

10.5 指标：成功率、步数、工具错误、成本与 P99

指标是从 span 聚合出来的投影，它的价值在于趋势与分层，不在于解释单次运行。设计指标时先问三个问题：这个数用哪个分母？按什么维度切？切完的基数有多大？三问答错，指标就会在关键时刻给出错误的方向。

一组够用的 agent 指标：

这张表说明什么：八个指标里，只有 run_success_rate 是「结果」，其余都是「过程」。只盯结果，会在成功率不变的情况下错过成本翻倍、尾延迟恶化、工具错误率上升；只盯过程，会优化一堆局部指标却交付不了。两类要一起看，且必须能按 task 分层——不同任务的成功率与步数分布不可直接平均。

10.5.1 成功率与终止原因：分母决定含义

成功率的定义看起来没有歧义，实际上分母的选择会改变含义：

$$\text{success} = \frac{#{\text{验收通过}}}{#{\text{全部 run}}},\qquad \text{completion} = \frac{#{\text{stop_reason}=\text{done}}}{#{\text{全部 run}}}$$

两者不同：done 只表示宿主认为目标满足，不表示验收通过。一个 agent 可以在测试超时的情况下调用 finish，done 为真但验收为假（1.8 节的「假成功」）。对外报「成功率」时，分母应是有验收结果的 run；还在运行、被用户取消、因系统错误没跑完的 run 要单独列，不能悄悄从分母里删掉——那会让成功率随流量结构变化而虚高。

终止原因要作为独立指标按 reason 分桶，各桶占比之和为 1：

这张表说明什么：成功率是「结果指标」，终止分布是「过程指标」。一个把步数上限调到 1000 的系统，成功率可能上升，但 max_steps 桶会变厚、成本会上升；只看成功率会误判为改进。

10.5.2 步数：均值会掩盖长尾

步数分布高度偏斜：多数任务 3–6 步，少数任务几十步。均值 6.2 步可能意味着「大部分 5 步、少数 40 步」，也可能意味着「全部 6 步」；两者的成本与风险完全不同。所以要报分位数：

$$\text{P}95 = x_{(\lceil 0.95n\rceil)},\qquad \text{P}99 = x_{(\lceil 0.99n\rceil)}$$

下标是按升序排列后的第几个样本（nearest-rank）。$n=20$ 时 P99 就是最大值，$n=100$ 时 P99 是第 99 个；样本少于 100 时不要报 P99，报 max 并注明 $n$。本章实验只有 3 条 LLM span，jq 算出的 P95 是 610 ms（也就是最大值），这个数字只能验证口径，不能当性能结论。

步数长尾通常对应两类问题：模型在循环里试错（no_progress 之前的那段），或者工具失败后反复重试。把步数与终止原因交叉，能区分它们：max_steps 且工具错误率高，是工具问题；done 但步数 P99 很高，是策略在绕路。

10.5.3 工具错误：分成「首次失败」与「最终失败」

一个工具调用可能重试三次才成功。如果只统计最终结果，错误率接近 0，但用户等待了三次超时；如果只统计首次尝试，错误率很高，但系统其实自愈了。两个口径都要有：

$$\text{first-attempt error rate} = \frac{#{\text{第 1 次尝试失败}}}{#{\text{工具调用}}},\qquad \text{final error rate} = \frac{#{\text{所有尝试失败}}}{#{\text{工具调用}}}$$

重试有效率可以定义为 $1 - \text{final}/\text{first}$；它下降说明重试在做无用功（例如权限错误被当成瞬时错误重试）。分母是「工具调用」而不是「run」，因为一次 run 可能调用几十次工具；按 run 算会把不同工具的错误混在一起。

错误还要按类别分：传输（超时、连接重置）、业务（参数非法、对象不存在）、权限（scope 不足、策略拒绝）、系统（磁盘满、进程被杀）。四类的处置完全不同（第 1.2.5 节）：传输可重试，业务要让模型纠正，权限要终止或升级，系统要保留现场。只报一个总错误率，等于把四种病混成一个发烧。

10.5.4 成本与队列等待：两个最容易被平均掉的指标

成本要报三个数：每次 run 的 token、每次 run 的金额、每次成功的金额。第三个才是业务指标：

$$\text{cost per success} = \frac{\sum_{i} c_i}{#{\text{验收通过的 run}}}$$

单次成本下降但成功率下降得更快时，每次成功的成本反而上升——这是「便宜但没用」的典型。缓存命中的 token 要单独统计，否则 prompt caching 带来的成本下降会被误判为「模型变便宜了」。

队列等待是另一个容易归错因的指标。端到端延迟由「排队 + 模型 + 工具 + 重试 + 审批」组成；如果只按模型调用耗时做优化，而 P95 里 40% 是排队，优化模型不会改善用户体验。queue_wait_ms 从任务入队到 step 开始计时，按线程池/优先级分桶；它还能解释「同一模型、同一提示词，为什么下午变慢」——不是模型慢，是排队。

10.5.5 基数：指标系统的隐形预算

每个指标的时间序列数等于标签取值的笛卡尔积：

$$\text{series} = \prod_{l \in L} |l|$$

假设有 12 种任务、4 个模型、25 个工具、3 种状态，组合是 $12 \times 4 \times 25 \times 3 = 3600$ 条序列，尚可接受。再加一个 user_id（20 万），就是 $7.2 \times 10^8$ 条；再加 trace_id，每条 run 都是新序列，指标后端会直接被打穿。

这张表说明什么：标签是索引维度，不是「所有想得到的字段」。高基数字段放 span 属性，需要时按 trace_id 回查；指标只保留能分组、能告警、基数可控的维度。确实需要看单条时，用 exemplar（直方图里挂一个 trace_id 样本），而不是把 trace_id 变成标签。

10.6 回放：记录、重放、确定性边界与脱敏

回放常被误解为「把 agent 再跑一遍」。再跑一遍不是回放，是重新执行：模型可能采样到不同输出，工具可能产生第二次副作用，时间、网络、缓存都可能不同。真正的回放是用记录重建决策过程：给定同样的输入、同样的工具结果、同样的模型输出，验证控制流是否还走得通，以及两次运行在哪里分叉。

三个层次要分清：

这张表说明什么：记录回放是「用录像核对剧本」，重新执行是「再演一遍」。前者能证明「代码改动后，同样的输入还会走同样的路径」，后者只能证明「这次跑出来还不错」。生产事故的复盘应该用前者，因为你需要的是可比较、可重复的证据。

10.6.1 记录什么：覆盖所有非确定性输入

回放的可复现性不取决于记了多少，而取决于是否覆盖了所有非确定性输入。少记一个，重放就会在那一处分叉。

这张表说明什么：模型输出优先记录结果而不是「种子」。多数模型服务不保证 seed 可复现，跨版本更不可能；只有记录输出，回放才稳定。种子只用于「同版本、同参数下的探索」，不能作为回放的主要依据。

这个定义把「脱敏」写进了能力边界：脱敏不是回放之后的一个可选步骤，它直接决定回放能回答什么问题。把 prompt 全部替换成 <redacted>，你仍然能验证「第 3 步是否还调用同一个工具、预算是否还够」，但不能验证「模型是否因为那句话改变了决定」。

10.6.2 确定性边界：一个充分必要条件

这个定理的实用形式是一张检查表：模型输出、工具结果、时间、随机数、网络快照、缓存状态、并发顺序，逐项问「记录了没有」。任何一项缺失，回放就只能做到「结构一致」，不能做到「状态一致」。很多团队的回放系统看起来能跑，实际只是把最终答案打印了一遍——它验证的是「记录能读出来」，不是「决策能复现」。

10.6.3 脱敏后的回放：结构回放与语义回放

事故复盘经常要在「不能看原文」的环境里进行：外包团队、跨部门、合规审计。这时要把回放分成两种能力：

结构回放可以跑在脱敏数据上：保留 trace_id 的映射、span 名称、耗时、状态、预算与工具名，把参数与内容替换成哈希。它能发现「改了提示词后，第 3 步不再调用审批」这类结构回归，也能做差分对比；它不能发现「模型把退款金额算错了」这类语义错误。两种回放不是替代关系，而是不同权限下的不同证据。

语义回放要在隔离环境里做：独立的存储、短保留期、访问审计、禁止外网与副作用。不要在原生产 trace 库上开一个「查看原文」的开关——那等于把最敏感的数据放在访问控制最弱的地方。

10.6.4 差分回放：对齐两棵树

差分回放是回放最有工程价值的形式：同一批任务，改动前后各跑一次，把两棵 span 树对齐，逐节点比较状态、耗时、token 与决策。对齐的键不能是 span_id（每次都不同），而应是路径：从根开始，按「名字 + 同名兄弟的序号」构造，例如 invoke_agent support#0/step 3#0/execute_tool ticket.update#0。路径稳定，才能跨运行比较。

本章实验的差分输出（正常 run vs 断链 run）：

--- /tmp/ch10-trace.jsonl
+++ /tmp/ch10-broken.jsonl
- invoke_agent support#0/step 3#0/execute_tool ticket.update#0  trace=b27bc6882af7  parent=5ab2ae72  dur=240ms  ok
+ execute_tool ticket.update#0  trace=b72ba06b2229  parent=-  dur=240ms  ok
removed=1 added=1 changed=0  spans 11→11  traces 1→2

读这段 diff 要看三件事。第一，removed 的路径里带着完整的父链，说明工具原本挂在第 3 步下；第二，added 的路径只有一层，parent=-，说明它成了另一条 trace 的根；第三，traces 1→2 是结构性变化，比任何字段差异都严重。三行合起来就是断链的完整证据。如果只看「工具调用次数没变」，会以为两次运行等价。

差分要区分三类变化，处置完全不同：

耗时比较要带容差与样本量：单次运行的 240 ms 与 900 ms 可能只是网络抖动。结构变化可以单次判定（要么有要么没有），性能变化要多次采样后比 P50/P95。

回放的安全边界要写死在工具里，而不是文档里：

1. 默认不执行工具。 回放器只读记录；要重做副作用，必须显式进入沙箱、带幂等键、并有人批准。
2. 没有「跳过检查」的开关。 结构错误（断链、重复 id、负时长）不静默修复，报告并返回非零退出码；否则 CI 会把坏 trace 当成通过。
3. 回放包有保留期与访问控制。 它包含模型输入输出，敏感度等同于内容存储；不能和普通 trace 用同一套权限。
4. 差分门禁只拦结构回归，不拦单次耗时波动。 结构差异是确定的；耗时差异要先聚合，再判断是否超过阈值。门禁的多条件设计见 9.5 节。

10.7 失败案例：span 断链、时钟漂移与 TZ 空值

三个案例看起来无关：一个是上下文传播，一个是时钟同步，一个是时区解析。它们共享同一个形状——观测数据本身假设了一个不成立的前提。断链假设「子 span 总能看见父上下文」，漂移假设「所有机器的时间戳可比」，TZ 案例假设「本地时间字符串自带时区」。三个假设都不写在代码里，所以三个故障都不会抛异常；它们只是让证据变得不可信。

10.7.1 span 断链：异步工具没传 context

场景：写工单的工具被派发到一个工作线程执行，避免阻塞主循环。读工具是同步调用，写工具走 threading.Thread。代码看起来没问题，工具成功、结果正确、副作用只有一次。但 trace 变成了两条：

python3 experiments/ch10/tracer.py --break-chain --out /tmp/ch10-broken.jsonl

traces=2 spans=11
trace b27bc6882af7…  spans=10  start=2026-10-19T09:00:00.000+00:00
invoke_agent support  [1985ms] ok  查询退款到账时间并更新工单
   ├─ step 1  [+0ms +420ms] ok  #1
   │  └─ chat gpt-4.1-mini  [+0ms +420ms] ok  gpt-4.1-mini in=820 out=64 $0.000430
   ├─ step 2  [+420ms +300ms] ok  #2
   │  └─ execute_tool kb.search  [+0ms +300ms] ok  kb.search ok effect=read attempts=2
   └─ step 3  [+720ms +1265ms] ok  #3
      ├─ chat gpt-4.1-mini  [+0ms +610ms] ok  gpt-4.1-mini in=1240 out=72 $0.000611
      ├─ guard budget  [+610ms +5ms] ok  allow steps_remaining >= 3
      ├─ approval ticket.write  [+615ms +30ms] ok  approved by=policy:auto
      └─ chat gpt-4.1-mini  [+885ms +380ms] ok  gpt-4.1-mini in=1580 out=96 $0.000785
trace b72ba06b2229…  spans=1  start=2026-10-19T09:00:01.365+00:00
execute_tool ticket.update  [240ms] ok  ticket.update ok effect=write attempts=1

读这段输出，先看两个数字：traces=2 与第二条 trace 的 spans=1。正常运行时是 traces=1 spans=11（10.8 节）；现在写工具的 span 单独成了一条 trace，根是一个 execute_tool，没有 run，没有 parent，也没有 link。它发生的时间（09:00:01.365）落在第一条 trace 的 run 区间内，但两条 trace 之间没有任何结构关系。

结构检查器给出的判据：

python3 experiments/ch10/replay.py --trace /tmp/ch10-broken.jsonl --check

integrity: traces=2 spans=11 roots=2 linked_roots=0 status=broken
  orphan_spans=0 orphan_roots=1 duplicate=0 negative_duration=0 containment=0
  ! trace b72ba06b2229… 的根是 execute_tool ticket.update（kind=tool），没有 run span，也没有 link

这条报告的依据是 定理 10.2.1：根数从 1 变成 2，孤儿数为 0，说明多出来的是一个没有父节点的根，而不是一个 parent id 写错的孤儿。两种断链的形状不同，修法也不同：

根因只有一行：threading.Thread(target=fn) 不会复制 contextvars。正常路径用的是 copy_context()：

ctx = contextvars.copy_context()
worker = threading.Thread(target=ctx.run, args=(call_tool,))

copy_context() 复制的是「当前线程此刻的上下文快照」，所以工作线程里 _current.get() 能拿到 step 的 span，工具 span 自然挂在 step 下。修完之后 traces=1、roots=1，工具回到第 3 步的子树里。

跨进程时，contextvars 帮不上忙，要传 traceparent：

• HTTP/gRPC：标准 header；
• MCP：params._meta.traceparent（10.2.1）；
• 消息队列：把 traceparent 写进消息 envelope 的 header，消费端用它创建子 span；
• 批处理/异步任务：如果任务在时间上完全独立（run 结束后才开始），用 link 指回发起它的 span，不要伪造父子关系。

replay: status=incomplete trace=b27bc6882af7… steps=3 tool_calls=1 tools_executed=0 side_effects=0
  step 1  kb.search      <- record  ok=true  effect=read  span=0eaef954
  ! step 3: ticket.update 没有对应的 tool span（断链）

断链的代价不只是 waterfall 少一段。回放会缺一步（工具结果找不到），成本会漏算（工具 span 不在 run 子树里，按 trace 聚合时被算到另一条 trace），审计会断链（谁批准了这次写操作，与写操作本身不在同一条 trace）。三者的共同修复都是「让上下文过边界」，而不是「在展示层把两条 trace 拼起来」。

10.7.2 时钟漂移：waterfall 出现负值

场景：写工具跑在一台独立的 worker 上，这台机器的时钟比主进程慢 850 ms（VM 挂起恢复后 NTP 还没追上，或者容器宿主的时间同步出了问题）。工具本身的耗时是准确的 240 ms，但它的绝对时间戳整体提前了 850 ms，落在父 span 开始之前。只截取第 3 步的子树：

python3 experiments/ch10/tracer.py --worker-lag-ms 850 --out /tmp/ch10-lag.jsonl --tree

      ├─ execute_tool ticket.update  [-205ms +240ms] ok !!  ticket.update ok effect=write attempts=1
      ├─ chat gpt-4.1-mini  [+0ms +610ms] ok  gpt-4.1-mini in=1240 out=72 $0.000611
      ├─ guard budget  [+610ms +5ms] ok  allow steps_remaining >= 3

Δparent = -205ms：工具在「第 3 步开始」之前 205 ms 就开始了。真实原因是第 3 步的模型调用占 610 ms，工具在第 645 ms 才开始；减去 850 ms 的时钟偏移，就变成 -205 ms。文本瀑布图把负偏移标出来（只截取第 3 步及其两个子节点）：

waterfall  root=invoke_agent support  wall=1985ms  width=44
span                                Δparent      dur  timeline
  step 3                               720ms    1265ms  |               ############################ |
    execute_tool ticket.update        -205ms     240ms  |#####                                       |  ! negative offset
    chat gpt-4.1-mini                    0ms     610ms  |#############                               |

注意三件事。第一，工具条的起点被画在 timeline 的开头，因为它不能画在负数位置；这会让「工具先于父开始」看起来像「工具很早就跑了」。第二，dur 仍然是 240 ms，说明时长没坏，绝对时间坏了。第三，run 的 wall 仍然是 1985 ms，因为最大结束时间没变；如果偏移方向相反（worker 时钟快 850 ms），run 的 wall 会被拉长 850 ms，延迟指标会凭空变差。

结构检查器把它标成 containment 违规：

integrity: traces=1 spans=11 roots=1 linked_roots=0 status=broken
  orphan_spans=0 orphan_roots=0 duplicate=0 negative_duration=0 containment=1
  ! 子 span 早于父 span c7d32657（execute_tool ticket.update）Δparent=-205ms

这条检查的判据是 定义 10.2.1 的条件 4：父区间必须包含子区间。它抓得住「子早于父」和「子晚于父结束」，抓不住「两台机器同时偏移了同样的量」——后者不会产生负值，但会让不同 trace 之间的时间比较失真。所以除了结构检查，还要记录时钟偏移。

这里有一条容易写反的规则：因果顺序来自 parent 关系，不来自时间戳。排序、重放、瀑布图都应该先按父子关系遍历，再把时间戳用于宽度与偏移。反过来做（先按时间排序，再猜父子）在断链与漂移同时出现时会得到完全错误的调用栈。第 3 章讲进程监控时也强调过：墙钟会跳，单调时钟不会；跨机器比较墙钟，本来就不成立。

10.7.3 TZ 空值：审计时间整体偏移

场景：审计服务把每次审批写成 datetime.now().strftime("%Y-%m-%d %H:%M:%S")，不带时区偏移。部署时容器环境里有一个空的 TZ=（来自 compose 的 - TZ= 或 K8s 里引用了一个未设置的变量）。产品预期是北京时间，进程却按 UTC 解释本地时间，于是「22:10 的审批」被写成「14:10」，保留期任务按本地时间解析，提前 8 小时删除了记录。

先看 libc 的规则，三条命令，同一个瞬间：

printf 'default: '; date '+%Y-%m-%dT%H:%M:%S%z %Z epoch=%s'
printf 'TZ=    : '; TZ= date '+%Y-%m-%dT%H:%M:%S%z %Z epoch=%s'
printf 'TZ=bad : '; TZ=Not/AZone date '+%Y-%m-%dT%H:%M:%S%z %Z epoch=%s'

default: 2026-10-19T09:58:41+0800 CST epoch=1792375121
TZ=    : 2026-10-19T01:58:41+0000 UTC epoch=1792375121
TZ=bad : 2026-10-19T01:58:41+0000 UTC epoch=1792375121

三行的 epoch 完全相同（1792375121），说明瞬间没变，只是解释变了。TZ 为空串、或值无法解释时，tzset 的行为是 UTC，不是「系统时区」，也不是「报错」；这是必须写对的一条，很多团队在这里写反。TZ 完全没有设置时，才走 /etc/localtime。

Python 侧同样如此：

TZ= python3 -c "import time; time.tzset(); print(time.strftime('%Z %z'), time.timezone)"

UTC +0000 0

tzset() 的语义值得单独记：它读当前进程环境里的 TZ，更新 tzname、timezone、daylight 等全局量；改了 TZ 之后不调用 tzset()，不同 API 可能给出不一致的读数。本机（Darwin 27.0.0 / Python 3.13）实测：

TZ= python3 -c "
import os, time
time.tzset()
print('after tzset :', time.strftime('%Z %z'), time.tzname, time.timezone)
os.environ['TZ'] = 'Asia/Shanghai'
print('no tzset    :', time.strftime('%Z %z'), time.tzname, time.timezone)
time.tzset()
print('tzset again :', time.strftime('%Z %z'), time.tzname, time.timezone)
"

after tzset : UTC +0000 ('UTC', 'UTC') 0
no tzset    : CST +0800 ('UTC', 'UTC') 0
tzset again : CST +0800 ('CST', 'CST') -28800

中间一行是最危险的：strftime 已经按新时区输出 CST +0800，但 time.tzname 还停在 ('UTC','UTC')，time.timezone 还是 0。如果代码用 time.timezone 自己算偏移，就会和 strftime 的输出差 8 小时。不同 libc 对 localtime 是否每次重读 TZ 有差异，可移植的结论只有一条：改 TZ 后必须调用 tzset()，不要在同一进程里边改边格式化。

还有两个变体：

1. tzdata 缺失。 容器里没有 /usr/share/zoneinfo（例如 alpine 没装 tzdata），TZ=Asia/Shanghai 不会报错，而是静默回退 UTC。tzset() 没有返回值，无法从调用处发现失败；只能在启动时校验 tzname 或 tm_gmtoff，并在镜像里显式安装 tzdata。本机无法用 TZDIR 复现（macOS 的 libc 忽略 TZDIR），所以上面的 TZ=Not/AZone 走的是同一条「区名解析失败 → UTC」路径。
2. POSIX TZ 字符串的符号是反的。 POSIX 的偏移量是「加到本地时间上得到 UTC」的值，符号与常见的 UTC+8 相反：TZ=CST-8 表示本地时间比 UTC 快 8 小时，TZ=CST+8 则表示慢 8 小时。本机实测 TZ=CST-8 date 输出 09:53 CST，TZ=CST+8 date 输出前一天 17:53 CST。手写 POSIX 规则时把符号写反，会得到一条稳定的、错误的 8 小时偏移——比空值更难发现。

三个案例放在一起，是因为它们的修复都指向同一个原则：证据的每个字段都要带足够的上下文，才能在另一台机器、另一个进程、另一个时区里被正确解释。span 要带 parent，时间戳要带偏移与时钟源，日志要带 trace_id。缺一个，数据还在，但证据失效了。

这张表说明什么：三类失败的共同点是「字段缺失或语义不明」，而不是「组件坏了」。它们不会被重试、扩容或换模型修好；只能靠 schema 与检查修好。检查本身要能失败——返回非零退出码、发告警、阻断发布，否则它只是文档。

10.8 实验：最小 tracer + 回放

experiments/ch10/ 用三个 Python 文件加一个 README 把本章压成可运行的最小实现：一个 span/trace 记录器、一个回放与差分器、一组把不变量钉死的测试。纯标准库、无网络、默认虚拟时钟；同样的命令跑两次，输出逐字节相同，可以直接进 diff 或当金标。

它不接 OTel SDK、不发 OTLP、不做真实采样，所以不能当生产组件；它的用途是让正文的每个概念都有一个可检查的字段与一条可复现的命令。

10.8.1 正常跑一遍

python3 experiments/ch10/tracer.py --out /tmp/ch10-trace.jsonl

traces=1 spans=11
trace b27bc6882af7…  spans=11  start=2026-10-19T09:00:00.000+00:00
invoke_agent support  [1985ms] ok  查询退款到账时间并更新工单
   ├─ step 1  [+0ms +420ms] ok  #1
   │  └─ chat gpt-4.1-mini  [+0ms +420ms] ok  gpt-4.1-mini in=820 out=64 $0.000430
   ├─ step 2  [+420ms +300ms] ok  #2
   │  └─ execute_tool kb.search  [+0ms +300ms] ok  kb.search ok effect=read attempts=2
   └─ step 3  [+720ms +1265ms] ok  #3
      ├─ chat gpt-4.1-mini  [+0ms +610ms] ok  gpt-4.1-mini in=1240 out=72 $0.000611
      ├─ guard budget  [+610ms +5ms] ok  allow steps_remaining >= 3
      ├─ approval ticket.write  [+615ms +30ms] ok  approved by=policy:auto
      ├─ execute_tool ticket.update  [+645ms +240ms] ok  ticket.update ok effect=write attempts=1
      └─ chat gpt-4.1-mini  [+885ms +380ms] ok  gpt-4.1-mini in=1580 out=96 $0.000785

11 个 span 的构成是 1 个 run、3 个 step、3 个 llm、2 个 tool、1 个 guard、1 个 approval。kb.search 的第一次超时没有变成额外的 span，而是变成一个 retry 事件：重试是同一个操作的过程，不是两个操作；如果每次重试都开一个 span，工具调用数会虚高，错误率也会被重复计数。

机器可读的摘要：

python3 experiments/ch10/tracer.py --out /tmp/ch10-trace.jsonl --summary \
  | jq '{traces,spans,steps,tool_calls,cost_micros,wall_ms,side_effects}'

{
  "traces": 1,
  "spans": 11,
  "steps": 3,
  "tool_calls": 2,
  "cost_micros": 1826,
  "wall_ms": 1985.0,
  "side_effects": 1
}

cost_micros=1826 可以手算。实验用的示例价目是输入 0.40、输出 1.60 美元每百万 token（不是任何厂商的报价）：三次调用分别是 820×0.40 + 64×1.60 = 430.4、1240×0.40 + 72×1.60 = 611.2、1580×0.40 + 96×1.60 = 785.6；代码对每次调用取整后相加，得到 430 + 611 + 785 = 1826 微美元。side_effects=1 是写工单的次数，回放时这个数必须保持 1。

10.8.2 校验与重放

python3 experiments/ch10/replay.py --trace /tmp/ch10-trace.jsonl

integrity: traces=1 spans=11 roots=1 linked_roots=0 status=ok
  orphan_spans=0 orphan_roots=0 duplicate=0 negative_duration=0 containment=0
replay: status=replayed trace=b27bc6882af7… steps=3 tool_calls=2 tools_executed=0 side_effects=0
  step 1  kb.search      <- record  ok=true  effect=read  span=0eaef954
  step 3  ticket.update  <- record  ok=true  effect=write  span=c7d32657
  answer: 退款按支付渠道 3 到 5 个工作日到账，工单 T-1042 已更新。
  answer_source: span attribute app.answer（不是重新生成）

三处读数。第一，status=ok 是结构校验的结论：根唯一、无孤儿、无重复、无负时长、无 containment 违规。第二，tools_executed=0 side_effects=0 是回放的安全证明：两次工具调用的结果都来自记录，ticket.update 没有第二次执行。第三，answer_source 明确写了答案来自 span 属性，不是重新调用模型生成的——这句话决定了这份输出能不能当审计证据。

10.8.3 用 jq 做四类聚合

不需要先上平台，jq 就能把 JSONL 变成指标：

# 1) span 类型分布：先确认采集没有漏 kind
jq -r 'select(.type=="span") | .kind' /tmp/ch10-trace.jsonl | sort | uniq -c

   1 approval
   1 guard
   3 llm
   1 run
   3 step
   2 tool

# 2) 按 trace_id 聚合：步数、工具数、成本（微美元）
jq -sr 'map(select(.type=="span")) | group_by(.trace_id)
  | map([.[0].trace_id[0:12],
         (map(select(.kind=="step"))|length),
         (map(select(.kind=="tool"))|length),
         (map(.attributes["app.cost.micros"] // 0)|add)] | @tsv)[]' \
  /tmp/ch10-trace.jsonl

b27bc6882af7	3	2	1826

# 3) 工具错误率：这里只看最终结果，重试成功不算错
jq -sc 'map(select(.type=="span" and .kind=="tool"))
  | {tools: length, errors: (map(select(.attributes["app.tool.ok"] == false))|length)}' \
  /tmp/ch10-trace.jsonl

{"tools":2,"errors":0}

# 4) LLM 延迟分位（nearest-rank）；n=3 时 p95 就是最大值
jq -sc 'map(select(.type=="span" and .kind=="llm") | .duration_ms) | sort
  | {n: length, p50: .[((length*50/100)|floor)], p95: .[((length*95/100)|floor)]}' \
  /tmp/ch10-trace.jsonl

{"n":3,"p50":420.0,"p95":610.0}

四条命令对应四类问题：类型分布查采集完整性，按 trace 聚合查成本与路径，错误率查工具可靠性，分位查尾部。第四条的 n=3 必须和数字一起读：3 个样本的 P95 只是最大值，报 P99 会更荒谬。真实系统里这三个数要按 task、model、tool 分层，且样本量至少几百。

日志与 span 的关联也能直接查：

jq -r 'select(.type=="log" and .level=="WARN")
  | [.ts, .event, .trace_id[0:12], .span_id[0:8], .fields.error] | @tsv' \
  /tmp/ch10-trace.jsonl

2026-10-19T09:00:00.540+00:00	tool.retry	b27bc6882af7	0eaef954	ETIMEDOUT

span_id 的前 8 位与 execute_tool kb.search 的 span 相同，所以这条 WARN 能准确落到那次重试上，而不是落到整个 step 或整条 run。

断链与时钟漂移用同一套命令复现：

python3 experiments/ch10/tracer.py --break-chain --out /tmp/ch10-broken.jsonl
python3 experiments/ch10/replay.py --diff /tmp/ch10-trace.jsonl /tmp/ch10-broken.jsonl
python3 experiments/ch10/tracer.py --worker-lag-ms 850 --out /tmp/ch10-lag.jsonl --waterfall
python3 experiments/ch10/replay.py --trace /tmp/ch10-lag.jsonl --check

第一条与第二条的输出见 10.6.4（一行 removed、一行 added、traces 1→2，退出码 1）；第三条与第四条见 10.7.2（Δparent=-205ms、containment=1，退出码 1）。两个非零退出码都是预期行为：结构坏了，工具不应该假装成功。

10.8.4 测试：25 条不变量

python3 -m unittest discover -s experiments/ch10 -v

test_break_chain_splits_trace (test_trace.BrokenChainTest.test_break_chain_splits_trace) ... ok
test_normal_trace_replays_all_recorded_tools (test_trace.BrokenChainTest.test_normal_trace_replays_all_recorded_tools) ... ok
test_replay_is_incomplete_when_tool_missing (test_trace.BrokenChainTest.test_replay_is_incomplete_when_tool_missing) ... ok
test_lag_keeps_duration_but_moves_timestamp (test_trace.ClockDriftTest.test_lag_keeps_duration_but_moves_timestamp) ... ok
test_tree_marks_negative_offset (test_trace.ClockDriftTest.test_tree_marks_negative_offset) ... ok
test_worker_lag_creates_negative_offset (test_trace.ClockDriftTest.test_worker_lag_creates_negative_offset) ... ok
test_duplicate_span_id_detected (test_trace.DetectorTest.test_duplicate_span_id_detected) ... ok
test_negative_duration_detected (test_trace.DetectorTest.test_negative_duration_detected) ... ok
test_no_run_root_detected (test_trace.DetectorTest.test_no_run_root_detected) ... ok
test_orphan_span_detected (test_trace.DetectorTest.test_orphan_span_detected) ... ok
test_diff_finds_missing_tool_and_new_root (test_trace.DiffTest.test_diff_finds_missing_tool_and_new_root) ... ok
test_identical_traces_have_empty_diff (test_trace.DiffTest.test_identical_traces_have_empty_diff) ... ok
test_roundtrip_and_required_fields (test_trace.JsonlTest.test_roundtrip_and_required_fields) ... ok
test_async_followup_uses_link_not_parent (test_trace.LinkTest.test_async_followup_uses_link_not_parent) ... ok
test_answer_comes_from_record (test_trace.ReplaySafetyTest.test_answer_comes_from_record) ... ok
test_replay_does_not_execute_side_effects (test_trace.ReplaySafetyTest.test_replay_does_not_execute_side_effects) ... ok
test_replay_never_imports_tool_implementation (test_trace.ReplaySafetyTest.test_replay_never_imports_tool_implementation) ... ok
test_empty_tz_is_utc (test_trace.TimezoneTest.test_empty_tz_is_utc) ... ok
test_uninterpretable_tz_is_utc (test_trace.TimezoneTest.test_uninterpretable_tz_is_utc) ... ok
test_valid_zone_is_not_utc (test_trace.TimezoneTest.test_valid_zone_is_not_utc) ... ok
test_different_seed_different_trace_id (test_trace.TraceShapeTest.test_different_seed_different_trace_id) ... ok
test_every_non_root_has_parent_in_same_trace (test_trace.TraceShapeTest.test_every_non_root_has_parent_in_same_trace) ... ok
test_ids_and_traceparent_are_w3c_shaped (test_trace.TraceShapeTest.test_ids_and_traceparent_are_w3c_shaped) ... ok
test_normal_trace_has_single_root_and_valid_tree (test_trace.TraceShapeTest.test_normal_trace_has_single_root_and_valid_tree) ... ok
test_same_seed_same_bytes (test_trace.TraceShapeTest.test_same_seed_same_bytes) ... ok

----------------------------------------------------------------------
Ran 25 tests in 0.046s

OK

25 个测试分四组：结构（父子、唯一、根）、失败模式（断链、漂移、孤儿、重复、负时长）、回放安全（不执行副作用、不 import 工具实现、答案来自记录）、时区（空值、不可解析、有效区）。它们证明契约没有被实现破坏，不证明观测系统在生产可用；生产可用要靠采样、存储、权限与保留期的工程。

10.8.5 三组只改一个变量的对照

第一组证明结构检查能抓住「工具还在、父子没了」；第二组证明时长与绝对时间是两件事；第三组证明可复现来自虚拟时钟，不是来自「代码没改」。三组都只改一个开关，所以结论可以归因——这也是第 9 章讲的对照原则在观测实验里的用法。

设计上有四个刻意的选择。第一，虚拟时钟只在 advance_ms() 时前进，基准是 2026-10-19T09:00:00Z，所以树、瀑布、JSONL 都能逐字节复现。第二，trace_id/span_id 由 blake2s(run_id:seed) 派生，形状符合 W3C（32/16 hex），但不是随机数；生产环境应换成密码学随机，避免可预测。第三，traceparent 在 span 内部生成——参数在 span 创建前求值，如果写成 span(name, attrs={"traceparent": tracer.traceparent()})，拿到的是父 span 的 id；这个坑在真实 SDK 里同样存在。第四，replay.py 不 import tracer，从依赖上保证它没有执行工具的能力，而不是靠一个「默认关闭」的开关。

母本对应

读这张表要抓住两点。对操作系统母本只做交叉引用：时间线、单调钟、TZ/tzset 的机制在 2.11 已经讲过，本章只写「这些机制如何让 agent 的证据失效」。对 W3C 与 OTel 取字段与规则：traceparent 的格式、span kind 的语义、gen_ai.* 的名字，都是可以直接落地的契约；Dapper 与 Tail at Scale 只借概念，不重复论文的测量。

本章陷阱

这张表说明什么：十二个陷阱里，前四个是「记什么」，中间四个是「怎么关联」，后四个是「怎么解释与复现」。它们都不是模型能力问题，换一个更强的模型不会自动消失；相反，模型越强，错误证据的说服力越大。

本章出口检查

下一站：11 安全 把 trace 里「不可信内容在什么时候获得了执行权」这条路径展开成攻击面：prompt injection、数据外泄、工具投毒与出口约束。