这个坑值得记一笔。7B 模型流式接口,用 curl 观察发现第一个 delta 只用了 800ms,但最后几个字之间空了一秒多,整段 600 字生成完用了 12 秒,服务端日志里每个 token 的处理时间都在 15ms 左右。
刚开始盯着「客户端每次 read 只取一个事件,处理慢反过来压住读循环」,折腾了半个多小时,排掉了。
排查方向其实有限,先把可能性排一排。生成到末尾时上下文长度变长,单步 decode 的时间随序列线性上升;输出侧没有设置 chunk 缓冲,网关按 4KB 攒够才下发,短尾块被留在缓冲里;服务端开了 max_tokens 上限,接近上限时在等 stop 判定而多跑了几步。
动手时先让curl 把每帧的到达时间打出来定位空档
curl -N -s -w '%{time_starttransfer}\n' http://127.0.0.1:8000/v1/chat/completions -H 'Content-Type: application/json' -d '{"model":"qwen","stream":true,"messages":[{"role":"user","content":"写一段600字的说明"}]}'
再往下把响应时间戳落到文件里逐帧比对
python -c "import time,requests;t0=time.time();[print(round(time.time()-t0,2)) for _ in requests.post('http://127.0.0.1:8000/v1/chat/completions',json={'model':'qwen','stream':True,'messages':[{'role':'user','content':'写一段600字的说明'}]},stream=True).iter_lines()]"
接着在 nginx 侧关掉响应缓冲只留 SSE 必须的头
nginx -s reload && curl -I http://127.0.0.1/v1/chat/completions -H 'Accept: text/event-stream'
剩下的就是记录每次生成的 token 数换算单步耗时
python -c "print(12.0/600*1000,'ms per token')"
怎么算真的好了,看的是同一批现象。相邻两个 delta 的间隔稳定在 20ms 上下,最后一块在生成结束后 50ms 内到达,客户端打印的总耗时与 token 数乘单步耗时基本吻合。
首包快不代表流式健康,尾块慢多半是序列变长加上缓冲攒包,两头都要看,只优化首字会把问题推到后半段。报错文案容易误导,真正的原因往往在相邻那一层的日志里。
