`total_ms`）¶

读者：看账本、做时间归因的人｜实现体：proxy.py｜变更档案：SOP.md

1. 概览¶

字段	含义	起止点
`ttfb_ms`	上游响应头到达耗时（含 TCP/TLS 建连、请求上传、上游排队与首 token 前的思考）	请求发出前 → `getresponse()` 返回后
`first_chunk_ms`	上游首个正文块到达耗时（≈ 首 token 时间）	同上 → 首个非空 chunk 读出时
`total_ms`	上游生成结束耗时（最后一个正文块到达）	同上 → 最后一个非空 chunk 读出时

三者恒满足 ttfb_ms ≤ first_chunk_ms ≤ total_ms。它们是代理侧观测：不含客户端消费速度（取时点在写回客户端之前），也不含最后一块的回写与连接关闭。缺失即不写键——重启代理前产生的记录、以及上游异常（502）路径，都没有这三个字段。

与工具侧埋点的分工：本字段管「上游生成侧」，logs/tool_timing.jsonl 管「工具执行侧」，两者相加即可解释一步间隔（步间隔 ≈ 生成 + 工具 + 客户端与代理往返）。

2. 位置¶

用途	路径
数据	`~/Documents/services/token_proxy/logs/usage.jsonl`（append-only，绝不可删）
实现	`~/Documents/services/token_proxy/proxy.py`（`_forward` / `_relay` / `_record`）
离线验证	`~/Documents/services/token_proxy/upstream-timing-20261007/verify_upstream_timing.py`
生效方式	改完须 `systemctl --user restart token-proxy`（重启会打断在途流式回答）

3. 日常速查表¶

# ① 最近一条的三个字段（确认在采集）
tail -n 1 ~/Documents/services/token_proxy/logs/usage.jsonl | python3 -c "import json,sys;d=json.load(sys.stdin);print({k:d.get(k) for k in ('ts','route','ttfb_ms','first_chunk_ms','total_ms')})"

# ② 采集覆盖率（重启后应逐步趋近 100%）
cd ~/Documents/services/token_proxy && python3 -c "
import json
n=h=0
for ln in open('logs/usage.jsonl',encoding='utf-8',errors='replace'):
    try: d=json.loads(ln)
    except ValueError: continue
    n+=1; h+= 1 if isinstance(d.get('ttfb_ms'),(int,float)) else 0
print('总记录 %d ｜ 含耗时字段 %d（%.0f%%）' % (n,h,100*h/n))"

# ③ 按分位看上游耗时（近 2000 条）
cd ~/Documents/services/token_proxy && python3 -c "
import json,statistics as st
from collections import defaultdict
g=defaultdict(list)
for ln in open('logs/usage.jsonl',encoding='utf-8',errors='replace').read().splitlines()[-2000:]:
    try: d=json.loads(ln)
    except ValueError: continue
    for k in ('ttfb_ms','first_chunk_ms','total_ms'):
        if isinstance(d.get(k),(int,float)): g[k].append(d[k])
for k in ('ttfb_ms','first_chunk_ms','total_ms'):
    v=sorted(g[k]) or [0]
    print('%-16s n=%-6d 中位=%8.0fms p90=%9.0fms max=%9.0fms' % (k,len(v),st.median(v),v[int(len(v)*0.9)-1],v[-1]))"

# ④ 生成侧净时长（total − first_chunk）≈ 吐字阶段
cd ~/Documents/services/token_proxy && python3 -c "
import json,statistics as st
v=[]
for ln in open('logs/usage.jsonl',encoding='utf-8',errors='replace').read().splitlines()[-2000:]:
    try: d=json.loads(ln)
    except ValueError: continue
    if isinstance(d.get('total_ms'),(int,float)) and isinstance(d.get('first_chunk_ms'),(int,float)):
        v.append(d['total_ms']-d['first_chunk_ms'])
v=sorted(v) or [0]
print('生成净时长（total−first_chunk）：n=%d 中位=%.0fms p90=%.0fms max=%.0fms' % (len(v),st.median(v),v[int(len(v)*0.9)-1],v[-1]))"

4. 日常操作¶

字段不想要了 / 想临时关掉：没有开关。最轻的做法是回滚 proxy.py（见 SOP.md 第 7 章）后重启；若只是想少看，分析时按 ② 的覆盖率过滤即可，不必改代码。

改了计时口径：改完 python3 -m py_compile proxy.py → 跑一次 python3 upstream-timing-20261007/verify_upstream_timing.py → 再重启。离线验证不可省，它是唯一能在不打断在线回答的情况下发现"字段为 0 / 缺键"的手段。

5. 配置项¶

本字段不引入任何配置项。相关常量只有假上游的验证延迟（在验证脚本里： HEADER_DELAY=0.30、CHUNK_GAP=0.15、CHUNKS=3），改它们只影响自测，不影响线上采集。

6. 备份与恢复¶

实现体备份：upstream-timing-20261007/backup/home/rain/Documents/services/token_proxy/proxy.py.bak.20261007-073146 （约 51 KB，权限同原文件）→ 恢复步骤见 SOP.md 第 7 章；
数据 logs/usage.jsonl 无自动备份且不可再生，需留档时手工 cp。

7. 监控与告警¶

指标	健康值	说明
字段覆盖率	重启后趋近 100%（历史段为 0 属正常）	速查表 ②
`ttfb_ms` 中位	与模型/时段相关，看趋势不看绝对值	突然整体翻倍 → 上游侧排队或网络异常
`ttfb_ms` p90 / max	无固定阈值	长尾常由上游排队造成，与断点无必然关系
「0 ms」或「负值」	应为 0 条	出现即说明计时点被改坏（需回滚）

8. 故障处置¶

场景 1：字段不出现（全部为 `None`）¶

症状：tail -n 1 的三个字段都是 None。

诊断

systemctl --user show token-proxy -p ActiveEnterTimestamp --value   # 看服务启动时间
stat -c '%y' ~/Documents/services/token_proxy/proxy.py              # 与上面对比
python3 -m py_compile ~/Documents/services/token_proxy/proxy.py && echo 语法通过

处置：服务启动时间早于 proxy.py 修改时间 → 说明没重启，执行 systemctl --user restart token-proxy（择无在途回答时）。语法不通过 → 按 SOP 第 7 章还原。

验证：再发一次请求，tail -n 1 三字段为数字且有序。

场景 2：字段恒为 0 或出现负值¶

症状：字段存在但等于 0，或 total_ms < first_chunk_ms。

诊断：说明三处改动没成套——常见是「取时点在 wfile.write() 之后」，或 sent_at 未随重发路径重置。

处置：按 SOP.md 第 5 章步骤 2 逐条核对三个取时点；改完先跑离线验证（会出现同类断言失败），通过后再重启。

验证：离线验证 15 项全通过；线上字段恢复有序。

场景 3：`total_ms` 明显大于客户端观测的墙钟¶

症状：记录里的 total_ms 比客户端实际等待时间长很多。

诊断：total_ms 只到「最后一个正文块读出」为止，正常应略小于客户端墙钟（差值 = 回写 + 连接关闭）。若明显更大，通常是上游 side 的长时间静默（等待生成），也可能是客户端中断后服务端仍在读——查 logs/proxy.log 是否有 客户端中断连接 告警。

处置：若告警频繁，属客户端行为（用户点停），非本字段缺陷；如需区分，可在分析时按 total_ms > 客户端墙钟 过滤后人工判读。

验证：连续观察若干条，正常请求应满足 total_ms ≤ 客户端墙钟。

9. 安全与权限¶

三个字段是数值，不含任何请求/响应内容，不涉及凭据；
不联网、不新增对外暴露面；
logs/usage.jsonl 权限沿用现有（664，属主 rain）。

10. 容量与性能¶

每行 +60 B；按日均 700 步估算 +40 KB/天（约 15 MB/年），无需轮转；
每步 3 次 time.monotonic()，纳秒级；
已验证：真实账本在离线验证期间零字节变化。

11. 附录¶

修订记录¶

日期	变更
2026-10-07	首次建立（字段上线，离线验证 15 项通过；生效需重启代理）

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

RUNBOOK：上游耗时字段（ttfb_ms / first_chunk_ms / total_ms）¶