3. vLLM请求日志详解：请求接收、排队、调度与完成
大家好，我是老张。今天我们来聊聊vLLM请求日志的四个核心阶段。说实话，很多运维同学看日志只会搜“error”，这太浪费了。vLLM的请求日志里藏着大量性能线索，你读懂了它，就等于拿到了系统的“心电图”。
核心观点：vLLM的请求生命周期分为四个阶段——接收、排队、调度、完成。每个阶段都有专属的日志特征和排查要点。
3.1 请求接收日志：第一道门
请求进来时，vLLM会打印一条类似这样的日志：
INFO 03-21 10:15:23 engine.py:123] Received request req_abc123: prompt="Hello, how are you?" prompt_len=12 max_tokens=256这条日志告诉你三件事：
- 请求ID（req_abc123）——后续所有日志都靠它关联
- 输入长度（prompt_len=12）——12个token，很短
- 最大输出长度（max_tokens=256）——用户想要256个token的回答
我个人习惯在这里加一个监控：如果连续收到prompt_len超过4096的请求，就要警惕了。我在项目中遇到过，某个业务方把整本书当prompt传进来，直接导致显存OOM。嗯，后来我们加了个前置拦截。
小技巧：用grep统计每分钟的“Received request”数量，就能算出QPS。我一般用这个命令：grep "Received request" vllm.log | wc -l
3.2 请求排队日志：等待的艺术
请求不会立刻被处理。vLLM内部有一个调度队列，日志长这样：
INFO 03-21 10:15:23 scheduler.py:45] Added request req_abc123 to waiting queue. Queue size: 3这里的关键指标是队列长度。你想想看，如果队列长度持续增长，说明处理速度跟不上请求速度。我曾经见过一个集群，队列长度冲到5000多，用户等得花儿都谢了。
为什么会这样？通常两个原因：
- 并发太高——请求量超过了模型的最大并发能力
- 显存不足——vLLM无法为请求分配KV Cache空间
我建议你重点关注这个日志：
WARNING 03-21 10:15:24 scheduler.py:78] Waiting queue is full (max=1024). Dropping request req_abc124.看到“Dropping request”了吗？这是系统在丢请求。我曾经踩过这个坑，当时以为是网络问题，查了半天才发现是队列满了。后来我们调大了--max-num-seqs参数，才缓解了这个问题。
避坑指南：我曾经把max-num-seqs设得太大（比如4096），结果显存爆了，vLLM直接crash。这个值要根据显存大小和模型参数量来算，别贪心。
3.3 请求调度日志：核心决策
调度阶段是vLLM最核心的部分。日志长这样：
INFO 03-21 10:15:24 scheduler.py:156] Scheduled req_abc123 (prefill). Block table size: 12, num_scheduled_tokens: 12
INFO 03-21 10:15:24 scheduler.py:160] Scheduled req_abc123 (decode). Block table size: 13, num_scheduled_tokens: 1这里有两个关键概念：
- prefill（预填充）——处理prompt阶段，一次性处理所有输入token
- decode（解码）——逐token生成输出，每次只处理1个token
你看，prefill阶段一次调度了12个token，而decode阶段每次只调度1个。这就是vLLM的“连续批处理”策略——把多个decode阶段的请求合并成一个batch，提高GPU利用率。
我个人习惯看num_scheduled_tokens这个值。如果prefill阶段这个值突然变小（比如从12降到2），说明系统在动态调整批大小。我在项目中遇到过，某个模型因为attention计算太慢，vLLM自动降低了prefill的token数来保证延迟。嗯，这时候就要考虑升级硬件了。
重要指标：调度日志中的“Block table size”代表当前请求占用的KV Cache块数。如果这个值持续增长，说明请求还没结束，显存占用在增加。
3.4 请求完成日志：收尾工作
请求处理完，vLLM会打印完成日志：
INFO 03-21 10:15:25 engine.py:200] Finished request req_abc123. Generated 256 tokens. Total latency: 2.34s. TTFT: 0.12s. TPOT: 8.7ms.这条日志包含三个黄金指标：
| 指标 | 含义 | 正常范围 |
|---|---|---|
| Total latency | 端到端延迟（从接收到完成） | 取决于模型和长度，一般几秒到几十秒 |
| TTFT | 首Token生成时间（Time to First Token） | 理想值 < 500ms |
| TPOT | 每Token输出时间（Time per Output Token） | 理想值 < 50ms |
说白了，TTFT反映的是“用户要等多久才能看到第一个字”，TPOT反映的是“生成速度有多快”。我建议你重点监控TTFT，因为用户对首字延迟最敏感。我曾经遇到一个case，TTFT飙到3秒多，用户反馈“点完发送，等了半天才出字”。后来发现是prefill阶段显存分配太慢，调整了--gpu-memory-utilization才解决。
实用技巧：用awk提取所有完成日志中的TTFT值，然后算P99：grep "Finished request" vllm.log | awk '{print $NF}' | sort -n | awk '{all[NR]=$1} END{print all[int(NR*0.99)]}'
3.5 知识体系总览
为了让你更直观地理解这四个阶段的关系，我画了一张流程图：
这张图把四个阶段串起来了。你想想看，从请求进来那一刻起，它就开始了这段旅程。每个阶段都有日志可查，每个阶段都有指标可监控。说白了，vLLM的日志系统设计得相当完善，关键是你得知道看哪里。
总结一下：请求接收日志告诉你“来了多少”，排队日志告诉你“等了多少”，调度日志告诉你“怎么跑的”，完成日志告诉你“跑得怎么样”。把这四个阶段串起来，你就能对vLLM的运行状态了如指掌。
好了，关于请求日志的四个阶段就聊到这里。记住，日志不是用来收藏的，是用来分析的。下次遇到性能问题，先翻翻这四个阶段的日志，大概率能找到线索。