先把当时的情况摆出来。看板上模型调用耗时 P50 显示 4.2 秒,用户体感的等待时间只有 0.8 秒,排查发现打点只记了请求结束时间,首包时间根本没有采集。
这类报错背后常见的原因有几处,逐个排除就行。只在响应结束后记录一次耗时。另一种情况是SDK 的流式迭代器没有埋首包回调。
另外,网关把流式响应缓冲后才转发,首包被推迟。少数情况下是日志里没有区分首包与末包字段。
上来先在流式迭代器第一次 yield 时打点
python -c "import time;t=time.time();print('ttft',time.time()-t)"
同时记录首包与末包两个时间戳
python stream_probe.py --url http://127.0.0.1:8000/v1/chat/completions --stream
接着检查反向代理是否开了缓冲
python -c "print({'proxy_buffering':'off','x_accel_buffering':'no'})"
末了在看板里把 TTFT 与总耗时分开画
python report.py --metrics ttft,total --in spans.jsonl
别只看报错消失,验证要多做一步。看板能同时看到 TTFT 与总耗时两条曲线,首包 P50 与用户体感一致,缓冲关闭后首包提前约 1.5 秒。
容易忽略的是,流式场景下总耗时和等待时间是两件事,只记一个数会让优化方向完全跑偏,两个指标都要落。如果同一现象隔几天又出现,说明根因没找到,别当偶发处理。
