SOP：工具执行埋点（tool-timing Hook）

主题目录：tool-timing-20261007/｜变更日期：2026-10-07｜实现体：tool-timing-hook/tool-timing.py

1. 背景

收尾自查的五组指标（A 效率 / B 成本 / C 积累 / D 工具 / E 手段）全部是 agent 侧—— 我自己的步数、token、工具合并、子智能体。被操作一侧（工具执行、远端命令、等待）没有任何口径。

而唯一的时间数据源 logs/usage.jsonl 只落 ts + token：两次落盘的差值 = 上游生成 + 工具执行 + 网络往返，三者不可分（proxy.py 的 _record() 不含任何耗时字段）。 2026-10-07 全量拆解显示：>60 s 的慢步只占 10.6%（2022 步）却吃掉 63% 的活跃时间（105 h / 167 h）， 但无法判断这些时间花在工具上还是花在生成上——这就是本次变更要解决的事。

2. 目标

变更完成后应达到的可验证状态：

1. logs/tool_timing.jsonl 每完成一次工具调用即追加一行，dur_ms 为该工具执行时长（毫秒）；
2. 能按工具类型聚合出「工具执行侧」的时长与占比，从而把步间隔拆成「生成侧 / 工具侧」；
3. 埋点绝不影响工具调用：任何异常静默 exit 0，不向 stdout 写任何内容；
4. 幂等：重复投递同一事件不产生第二行记录。

3. 前置条件

• Trae 客户端已支持 PreToolUse / PostToolUse Hook（本项目已有 6 个 Hook 在跑，满足）；
• 事件字段含 hook_event_name 与 tool_use_id（2026-09-23 由 posttooluse-guard/probe.jsonl 实测确认）；
• ~/.trae-cn/hooks.json 可写；
• 改 hooks.json 后必须重启 Trae 才生效（与 miss 无关，是客户端加载时机）。

4. 影响范围

项	说明
涉及主机	仅本机（Trae 客户端侧），不涉及任何远端主机、不涉及 token_proxy 服务
是否停服	否。重启 Trae 会中断当前会话的实时对话，但代理 token-proxy 服务不受影响
窗口期	无要求；建议在无在途任务时重启
新增开销	每次工具调用多 2 次 python3 启动，实测一对约 125 ms（不影响 p50 11 s 的步间隔）
新增落盘	logs/tool_timing.jsonl（append-only）+ tool-timing-hook/state/（1 h 自动回收）
上下文影响	零——两个事件均不输出 additionalContext，不向模型注入任何文本

5. 分步操作

步骤 1：部署 Hook 脚本

脚本已由本次变更创建于 tool-timing-hook/tool-timing.py。它由 hooks.json 直接以绝对路径调用， 不需要复制到别处，也不需要可执行位（命令行用 python3 <脚本> 调用）。

ls -l ~/Documents/services/token_proxy/tool-timing-hook/tool-timing.py   # 预期：文件存在
python3 -c "import ast,sys; ast.parse(open('$HOME/Documents/services/token_proxy/tool-timing-hook/tool-timing.py').read())"   # 预期：无输出（语法通过）

坑：脚本必须放在 tool-timing-hook/ 目录内——状态目录与日志路径均由脚本自身位置推导 （<脚本目录>/state、<脚本目录>/../logs/tool_timing.jsonl）。挪位置会同时挪走 state，日志落在新位置。

步骤 2：挂载 hooks.json（幂等）

在 PreToolUse 与 PostToolUse 各追加一条 matcher: "*" 的条目。下面的脚本可重复执行： 已挂载时报「零变更、全跳过」，未挂载时先备份再插入。

python3 - <<'PY'
import json, os, shutil, time
P = os.path.expanduser("~/.trae-cn/hooks.json")
CMD = ('s="$HOME/Documents/services/token_proxy/tool-timing-hook/tool-timing.py"; '
       '[ -f "$s" ] && python3 "$s" || true; exit 0')
ENTRY = {"matcher": "*", "hooks": [{"type": "command", "command": CMD, "timeout": 10}]}
d = json.load(open(P, encoding="utf-8"))
changed = []
for ev in ("PreToolUse", "PostToolUse"):
    items = d["hooks"].setdefault(ev, [])
    if any(CMD == h.get("command") for it in items for h in it.get("hooks", [])):
        continue
    items.append(json.loads(json.dumps(ENTRY)))
    changed.append(ev)
if changed:
    ts = time.strftime("%Y%m%d-%H%M%S")
    shutil.copy2(P, P + ".bak." + ts)
    json.dump(d, open(P, "w", encoding="utf-8"), ensure_ascii=False, indent=1)
    print("已挂载:", changed)
else:
    print("幂等检查：两条已挂载，本次零变更、全跳过")
PY

预期输出（已挂载时）：幂等检查：两条已挂载，本次零变更、全跳过。 坑：命令行结尾必须是 || true; exit 0——Hook 的退出码会被 Trae 当作协议， 非 0 会让整个工具调用失败（本项目其它 Hook 同理）。

步骤 3：确认生效（无需重启）

实测（2026-10-07）：hooks.json 改动即时生效，不必重启 Trae。 新增两条挂载后，下一次工具调用即开始落盘：hooks.json mtime 07:17:28 → 首条埋点 07:22:06， 期间未重启 Trae；65 条样本 miss_pre 全为 false、id_src 全为 tool_use_id。 原「须重启 Trae 才生效」的说法已证伪（旧结论基于"配置只在启动时读取"的推断，非实测）。

python3 -c "import json,os;d=json.load(open(os.path.expanduser('~/.trae-cn/hooks.json')));print([ 'tool-timing' in h['command'] for ev in ('PreToolUse','PostToolUse') for it in d['hooks'][ev] for h in it['hooks']].count(True), '条 tool-timing 挂载')"   # 预期：2 条

失败判断：挂载数为 2 但 logs/tool_timing.jsonl 长时间无新增 → 重启 Trae 兜底，再按第 8 章排查。 （LS matcher 对应的判据 G 是否同样即时生效未验证——guard_events 中尚无 G 记录。）

步骤 4：首次数据核对

重启后随便触发一次工具调用（如读一个小文件），再查看日志：

tail -n 5 ~/Documents/services/token_proxy/logs/tool_timing.jsonl

预期：出现形如 {"ts": "…", "dur_ms": 123.4, "tool": "Read", "llm_tool": "Read", "session": "…", "agent": "", "id_src": "tool_use_id", "miss_pre": false} 的行。

失败判断：重启后仍无新增行 → 核对 hooks.json 是否 JSON 合法、脚本路径是否存在； 重启后 miss_pre 恒为 true → Post 挂载了、Pre 未挂载（回到步骤 2 复查）。

6. 验证

层级	命令	预期
离线自测（18 项）	python3 tool-timing-20261007/verify_tool_timing.py	全部通过（0 项失败）；连跑两次同样通过（幂等）
结构校验	见步骤 3 的命令	2 条 tool-timing 挂载
真机	tail -n 5 logs/tool_timing.jsonl	有新增行，miss_pre: false
聚合可用	RUNBOOK 第 3 章「按工具聚合」命令	输出各工具的中位 / p90 / 合计占比

自测覆盖：Pre 静默、state 写入与回收、Post 落盘、dur_ms 合理、配对键来源、重复投递幂等、 孤立 Post（miss_pre=true）、非法输入（{} 之外的 5 种）静默、并行同名工具各记一行。

7. 回滚

备份位置：tool-timing-20261007/backup/home/rain/.trae-cn/hooks.json.bak.20261007-071701， 台账见 backup/README.md。

回滚步骤（二选一）：

# 方式 A：整体还原（会一并回滚本次之前的其它 hooks.json 改动，慎用）
cp -p ~/Documents/services/token_proxy/tool-timing-20261007/backup/home/rain/.trae-cn/hooks.json.bak.20261007-071701 ~/.trae-cn/hooks.json

# 方式 B：只摘除本次新增的两条（推荐）
python3 - <<'PY'
import json, os
P = os.path.expanduser("~/.trae-cn/hooks.json")
d = json.load(open(P, encoding="utf-8"))
for ev in ("PreToolUse", "PostToolUse"):
    d["hooks"][ev] = [it for it in d["hooks"][ev]
                      if not any("tool-timing.py" in h.get("command", "") for h in it.get("hooks", []))]
json.dump(d, open(P, "w", encoding="utf-8"), ensure_ascii=False, indent=1)
print("已摘除 tool-timing 挂载")
PY

回滚后必须重启 Trae 才生效。回滚后验证：hooks.json 内不再含 tool-timing.py，且工具调用不再新增日志行。

logs/tool_timing.jsonl 与 tool-timing-hook/state/ 是数据不是配置，回滚时不删—— 需要保留已采集的样本供分析。删除由用户对照 backup/README.md 自行决定。

8. 风险说明

风险	缓解
Hook 阻塞工具调用	脚本仅读写本地小文件，实测一对 ~125 ms；hooks.json 设 timeout: 10 秒
脚本异常导致工具失败	顶层 except Exception 静默 + sys.exit(0)；命令行再套 \|\| true; exit 0
PreToolUse 的 stdout 干扰协议	脚本不输出任何内容（自测含「stdout 为空」断言）
state/ 无界增长	保留期 1 h（STALE_SECONDS），Pre/Post 两端触发回收，删除写入 state/prune.log 留痕
埋点文本进上下文抬高成本	两个事件均不注入 additionalContext，零上下文成本
tool_use_id 缺失	退化为 <session>_<tool> 键（记 id_src: fallback），并行同名调用可能错配，仅兜底
误判「工具变慢」	本埋点量的是工具自身执行时长，不含模型生成；与步间隔含义不同，分析时勿混用

附录：交付物清单

文件	说明
tool-timing-hook/tool-timing.py	实现体（Pre/Post 双事件共用）
tool-timing-20261007/verify_tool_timing.py	离线自测（18 项，可重复运行）
tool-timing-20261007/SOP.md	本文档
tool-timing-20261007/RUNBOOK.md	运行与使用手册
tool-timing-20261007/backup/	hooks.json 备份与台账
logs/tool_timing.jsonl	产出数据（append-only，勿删）

---

来源：/home/rain/Documents/services/token_proxy/tool-timing-20261007/SOP.md ｜ 最后更新：2026-10-07 07:29（由 build/sync.py 同步，请勿在站点侧修改）