`total_ms`）¶

主题目录：upstream-timing-20261007/｜变更日期：2026-10-07｜实现体：proxy.py 关联：tool-timing-20261007/SOP.md（工具侧埋点，已完成并已生效）

1. 背景¶

工具侧埋点上线后，工具执行时长已有口径（首批 65 条样本：Edit 中位 6.5 s、Read 0.29 s）。但上游生成侧仍完全不可见：logs/usage.jsonl 只记 ts + token，两次落盘之差 = 生成 + 工具执行 + 网络往返，扣掉已知的工具侧后，"生成侧"仍是黑盒—— 既分不清「上游排队久」还是「生成 token 多」，也分不清「首 token 慢」还是「吐字慢」。

2. 目标¶

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

logs/usage.jsonl 每条正常记录新增三个字段（毫秒，1 位小数）： ttfb_ms（请求发出 → 响应头到达）、first_chunk_ms（→ 首个正文块，≈ 首 token）、 total_ms（→ 最后一个正文块，即上游生成结束）；
三者恒满足 ttfb_ms ≤ first_chunk_ms ≤ total_ms；
不改动任何转发行为：请求体、响应体、状态码、流式节奏与改动前逐字节一致；
旧记录与「上游异常」路径不产生该字段（不留键，读取方一律 .get()），向后兼容。

3. 前置条件¶

可写 proxy.py（属主 rain）；
代理由 systemd --user 托管（token-proxy.service），重启命令可用；
验证需要空闲端口 18898（代理实例）与 18899（假上游），二者当前均未被占用；
窗口要求：重启代理会打断在途流式回答，须择无任务窗口（见第 4 章）。

4. 影响范围¶

项	说明
涉及组件	仅代理本体（`proxy.py`，监听 `0.0.0.0:8788`）；不涉及上游服务商配置，不涉及客户端配置
是否停服	需要重启代理（秒级中断）。重启会切断所有在途流式回答——包括正在进行的对话
窗口期	无在途请求时执行；观察到的空档约 1~2 秒
落盘增量	每行约 +60 B（三个小数），按日均 700 步估算约 +40 KB/天
运行开销	每步 3 次 `time.monotonic()`（纳秒级），可忽略
客户端影响	无。字段只进代理自己的账本，不写回响应体

5. 分步操作¶

步骤 1：备份（高危前置，必做）¶

TS=$(date +%Y%m%d-%H%M%S)
cp -p ~/Documents/services/token_proxy/proxy.py \
      ~/Documents/services/token_proxy/upstream-timing-20261007/backup/home/rain/Documents/services/token_proxy/proxy.py.bak."$TS"
ls -l ~/Documents/services/token_proxy/upstream-timing-20261007/backup/home/rain/Documents/services/token_proxy/

预期：出现 proxy.py.bak.<时间戳>（约 51 KB）。未备份不得继续。

步骤 2：改三处（改动点逐条对照）¶

坑：三处必须成套改——只改其中一处不会报错，但字段要么不出现、要么恒为 0，且不会给出任何提示（这种"静默半成品"是本变更最主要的失败形态）。

import time（文件头 import 块，sys 与 threading 之间）；
_forward()：连接建立后取 sent_at = time.monotonic()， getresponse() 返回后写 meta["_t_sent"] / meta["_t_headers"]； thinking 重发路径要把 sent_at 重置为最终那一次（否则重发的请求会带上第一次的耗时）；
_relay()：流式循环里，每拿到一个非空 chunk 时取 now，首个记 first_at、每个记 last_at——取时点必须在 self.wfile.write() 之前，否则把"客户端消费速度"算进上游耗时；循环结束后写 meta["_t_first_chunk"] / meta["_t_last_chunk"]；
_record()：由 meta 取出四个时间戳，算出三个字段写进 entry （t_sent 缺失即整体跳过，保证旧路径不产生半截字段）。

cd ~/Documents/services/token_proxy
python3 -m py_compile proxy.py && echo "语法检查通过"
grep -n "_t_sent\|_t_headers\|_t_first_chunk\|_t_last_chunk\|^import time" proxy.py

预期：编译无输出（通过）；grep 命中 5 处左右（1 处 import + 4 处时间戳写入）。失败判断：语法错误 → 用第 7 章方式 A 还原后重做。

步骤 3：离线验证（上机前必做）¶

在 /tmp 起「假上游 + 临时配置的代理实例」，核对字段数值与假上游设定的延迟吻合。 该验证不会触碰真实 logs/usage.jsonl（脚本末尾有字节数不变的断言）。

cd ~/Documents/services/token_proxy
python3 upstream-timing-20261007/verify_upstream_timing.py; echo "退出码=$?"

预期：结果：全部通过（0 项失败），且打印 记录 1: ttfb=30x first_chunk=45x total=75x（假上游设定：响应头延迟 0.30 s、每块间隔 0.15 s × 3 块）。失败判断：字段为 None 或数量级不符 → 回到步骤 2 核对「三处是否成套改」；若报端口占用 → 关掉占用 18898/18899 的进程后重跑。

步骤 4：重启代理（高危：打断在途流式回答）¶

systemctl --user restart token-proxy
sleep 2; systemctl --user is-active token-proxy          # 预期：active
curl -s http://127.0.0.1:8788/healthz                    # 预期：{"status": "ok", ...}

坑：本次重启会同时启用此前挂起的「tools 顺序规范化」改动（见 tools-order-20261007/SOP.md），一次性生效两项，属预期内，无需分开处理。

步骤 5：首条数据核对¶

重启后随便发一次对话或请求，再看最后一条记录：

cd ~/Documents/services/token_proxy
tail -n 1 logs/usage.jsonl | python3 -c "import json,sys; d=json.load(sys.stdin); print({k: d.get(k) for k in ('ts','model','ttfb_ms','first_chunk_ms','total_ms','completion_tokens')})"

预期：三个字段均为数字且 ttfb ≤ first_chunk ≤ total。失败判断：三字段均为 None → 代理未重启成功（回到步骤 4）。

6. 验证¶

层级	命令	预期
语法	`python3 -m py_compile proxy.py`	无输出
离线（15 项）	`python3 upstream-timing-20261007/verify_upstream_timing.py`	全部通过；真实 usage 未被触碰
幂等	同上，连跑两次	两次均全部通过
真机	步骤 5 的一行命令	三字段为数字且有序
兼容	`grep -c '"total_ms"' logs/usage.jsonl` vs `wc -l logs/usage.jsonl`	前者 ≤ 后者（重启前的旧记录无该字段，属正常）

7. 回滚¶

备份位置：upstream-timing-20261007/backup/home/rain/Documents/services/token_proxy/proxy.py.bak.20261007-073146；台账见 backup/README.md。

# 方式 A：整体还原（推荐——本次只改一个文件）
cp -p ~/Documents/services/token_proxy/upstream-timing-20261007/backup/home/rain/Documents/services/token_proxy/proxy.py.bak.20261007-073146 \
      ~/Documents/services/token_proxy/proxy.py
python3 -m py_compile ~/Documents/services/token_proxy/proxy.py && echo "还原后语法通过"
systemctl --user restart token-proxy

回滚后验证：新记录不再含 ttfb_ms（旧字段不受影响，历史记录照旧可读）。 已采集的字段数据不删——它是观测数据，需要时用脚本过滤。

8. 风险说明¶

风险	缓解
改动破坏转发	只增计时与字段，不动请求体/响应体/状态码；离线验证含「响应被完整转发」断言；真实 usage 零触碰断言
逐 chunk 写客户端影响耗时读数	取时点放在 `wfile.write()` 之前，故 `total_ms` 不受客户端消费速度影响；`total_ms` 亦不含最后一块的回写与连接关闭
计时把重发路径算重	thinking 重发路径重置 `sent_at`，以最终那次请求为准
半成品改动静默通过	步骤 3 的数值断言（30x/45x/75x）能识别"字段存在但值为 0/None"
重启打断在途回答	择无任务窗口；重启前先确认无长流式回答在进行
字段撑大日志	每行 +60 B，量级可忽略

附录：交付物清单¶

文件	说明
`proxy.py`（改）	新增 `import time` + 四处计时写入 + `_record` 三字段
`upstream-timing-20261007/verify_upstream_timing.py`	离线验证（假上游 + 临时实例，15 项断言）
`upstream-timing-20261007/SOP.md`	本文档
`upstream-timing-20261007/RUNBOOK.md`	字段读取与聚合手册
`upstream-timing-20261007/backup/`	`proxy.py` 备份与台账

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

SOP：上游生成侧耗时埋点（proxy.py 新增 ttfb_ms / first_chunk_ms / total_ms）¶