3、请求处理日志分析：从排队到完成的完整旅程

大家好，我是你们的运维老司机。今天我们来聊聊vLLM请求处理的全链路日志分析。

说实话，刚开始接触vLLM的时候，我总觉得日志就是一堆没用的字符串。直到有一次线上服务突然变慢，用户投诉像雪片一样飞来，我才意识到——日志里藏着所有真相。你想想看，一个请求从进门到出门，经历了排队、预填充、解码、完成四个阶段，每个阶段都有它独特的"语言"。

嗯，今天我就带你读懂这些语言。

3.1 请求排队日志：第一道关卡

请求来了，第一件事就是排队。vLLM内部维护着一个调度队列，所有请求都得按规矩来。

典型的排队日志长这样：

INFO 03-25 10:15:23 scheduler.py:456] Added request req_001 to waiting queue. Queue size: 12
INFO 03-25 10:15:23 scheduler.py:489] Scheduling request req_001. Running: 8, Waiting: 11, Swapped: 0

这里有几个关键指标：

• Queue size：当前排队人数。我见过最夸张的一次，队列堆到了200+，那场面...
• Running：正在处理的请求数。这个值一般等于你的最大并发数。
• Waiting：还在等着的请求。如果这个数字持续增长，说明处理速度跟不上。
• Swapped：被换出到CPU的请求。嗯，这个后面细说。

还有一个容易被忽略的日志：

WARNING 03-25 10:15:24 scheduler.py:512] Request req_002 waiting time exceeds 30s. Consider reducing load.

这个警告一出现，基本可以断定你的服务扛不住了。要么加节点，要么限流。

3.2 预填充阶段日志：第一印象很重要

请求被调度后，进入预填充阶段。说白了，就是模型第一次看到你的prompt，需要把所有的输入token一次性算完。

日志示例：

INFO 03-25 10:15:24 model_runner.py:234] Prefill started for req_001. Input tokens: 2048, Block tables: 32
INFO 03-25 10:15:24 model_runner.py:278] Prefill completed for req_001. Latency: 0.342s, Throughput: 5994 tokens/s

预填充阶段我最关注两个指标：

指标	含义	正常范围
Input tokens	输入长度	取决于业务，一般几百到几千
Prefill latency	预填充耗时	通常几十毫秒到几秒
Throughput	吞吐量（tokens/s）	越高越好，但受限于显存带宽

还有一个细节：预填充阶段会分配KV Cache的block。日志里的Block tables: 32就是告诉你，这个请求占用了32个block。如果block分配失败，你会看到：

ERROR 03-25 10:15:24 block_manager.py:156] Failed to allocate blocks for req_001. Out of memory.

这个错误一出现，基本就是OOM了。要么调小max_num_seqs，要么加显存。

3.3 解码阶段日志：真正的性能战场

预填充完了，进入解码阶段。这是最耗时的部分，也是性能优化的主战场。

解码日志长这样：

INFO 03-25 10:15:24 model_runner.py:312] Decode step 1 for req_001. Batch size: 8, KV cache usage: 45%
INFO 03-25 10:15:24 model_runner.py:312] Decode step 2 for req_001. Batch size: 8, KV cache usage: 46%
...
INFO 03-25 10:15:25 model_runner.py:312] Decode step 50 for req_001. Batch size: 8, KV cache usage: 78%

解码阶段的核心指标：

• Decode step N：当前解码到第几步。每一步生成一个token。
• Batch size：当前batch里有多少请求。这个值越大，吞吐越高，但每个请求的延迟也会增加。
• KV cache usage：KV Cache使用率。超过80%就要警惕了。

我个人习惯把解码阶段的日志按时间画成折线图。如果看到Batch size突然下降，说明有请求完成了，或者被踢出了batch。如果KV cache usage持续增长，说明你的显存快撑不住了。

还有一个重要的日志：

WARNING 03-25 10:15:25 model_runner.py:345] Decode step 50 for req_001. Token generation speed: 12.5 tokens/s (below threshold 20 tokens/s)

这个警告说明生成速度太慢了。可能的原因：

1. 显存带宽饱和
2. 模型太大，计算瓶颈
3. batch里混入了长序列请求

3.4 请求完成日志：最后的告别

终于，请求处理完了。完成日志会告诉你最终的结果：

INFO 03-25 10:15:26 scheduler.py:612] Request req_001 finished. Status: SUCCESS. Total tokens: 2050, Total latency: 3.2s, TTFT: 0.35s, TPOT: 0.058s

这里有几个关键指标：

指标	含义	说明
TTFT	Time to First Token	用户感知到的首字延迟。一般要求小于1秒。
TPOT	Time Per Output Token	每个输出token的平均耗时。决定了生成速度。
Total latency	总耗时	从请求入队到完成的总时间。

如果看到Status: CANCELLED或Status: ERROR，那就得好好查查了：

ERROR 03-25 10:15:26 scheduler.py:620] Request req_003 finished. Status: ERROR. Reason: Client disconnected.
WARNING 03-25 10:15:26 scheduler.py:625] Request req_004 finished. Status: CANCELLED. Reason: Timeout after 60s.

客户端断开连接，可能是用户等不及了。超时取消，说明你的服务响应太慢。这两个问题，说白了都是性能问题。