第三节：vLLM日志格式解析——请求日志、调度日志、GPU内存日志、错误日志分类
日志这东西，平时没人爱看，出事了又恨不得它能开口说话。我在生产环境里踩过的坑，十有八九都是靠日志揪出来的。vLLM的日志体系其实挺清晰的，但如果你不熟悉它的分类和格式，排查问题就像大海捞针。
今天我就带你把这四种日志彻底吃透：请求日志、调度日志、GPU内存日志、错误日志。嗯，咱们一个一个来。
3.1 请求日志：每个请求的“身份证”
请求日志记录的是每一次推理请求的完整生命周期。说白了，就是谁来了、什么时候来的、花了多久、结果怎么样。
我个人习惯在排查性能瓶颈时，先看请求日志。它能直接告诉你延迟到底卡在哪一步。
3.1.1 日志格式示例
INFO 02-15 10:23:45 scheduler.py:789] Request 0x7f8c4a001b20: prompt_tokens=128, generated_tokens=256, ttft=45.2ms, itl=12.3ms, total_latency=3.2s这条日志里包含了几个关键字段：
- Request ID：0x7f8c4a001b20，每个请求的唯一标识
- prompt_tokens：输入的长度，128个token
- generated_tokens：生成的token数，256个
- ttft：Time To First Token，首token延迟45.2ms
- itl：Inter-Token Latency，后续每个token的平均生成时间12.3ms
- total_latency：总耗时3.2秒
关键指标解读：
- ttft > 200ms：说明调度或显存分配有瓶颈
- itl > 50ms：模型推理速度可能受限于GPU计算能力
- total_latency 异常高：可能是排队等待时间过长
3.1.2 请求日志的级别
vLLM默认只输出INFO级别的请求日志。如果你需要更细粒度的信息，可以调整日志级别：
# 启动时设置日志级别
python -m vllm.entrypoints.openai.api_server \
--model meta-llama/Llama-2-7b-hf \
--log-level DEBUG我曾经在生产环境里开过一次DEBUG级别，结果日志量直接暴涨了10倍，磁盘差点被打满。嗯，这个教训挺深刻的——调试完记得切回INFO。
3.2 调度日志：看清“排队”的真相
调度日志是vLLM最核心的日志之一。它记录了请求如何被分配到GPU上、什么时候开始执行、什么时候结束。
你想想看，如果多个请求同时到达，vLLM的调度器会怎么处理？调度日志就是答案。
3.2.1 调度事件日志
INFO 02-15 10:23:45 scheduler.py:234] Scheduling request 0x7f8c4a001b20: priority=0, num_scheduled_blocks=4, remaining_blocks=2
INFO 02-15 10:23:45 scheduler.py:256] Preempting request 0x7f8c4a001b30: reason=long_context, preempted_blocks=3这里有两个关键事件：
- Scheduling：请求被调度，分配了4个block，还剩2个block待处理
- Preempting：请求被抢占，原因是长上下文（long_context），被抢占了3个block
注意： 抢占（Preemption）是vLLM调度中常见的现象。如果频繁出现，说明显存资源紧张，或者请求的上下文长度差异太大。我曾经遇到过一个案例，某个用户的prompt特别长，导致其他短请求频繁被抢占，整体吞吐量直接腰斩。
3.2.2 调度队列状态
INFO 02-15 10:23:46 scheduler.py:312] Running queue: 3 requests, waiting queue: 5 requests, free blocks: 12/64这条日志告诉你当前系统的负载情况：
- Running queue：正在执行的请求数
- Waiting queue：等待中的请求数
- Free blocks：空闲的显存block数/总数
如果free blocks长期低于10%，说明显存快满了，需要扩容或优化。
3.3 GPU内存日志：显存管理的“晴雨表”
GPU内存日志是排查OOM（Out Of Memory）和显存泄漏的利器。vLLM使用PagedAttention管理显存，内存日志会详细记录每个block的分配和释放情况。
3.3.1 内存分配日志
INFO 02-15 10:23:45 memory.py:123] Allocated block 0x7f8c4a003200 for request 0x7f8c4a001b20, size=16KB
INFO 02-15 10:23:45 memory.py:145] Freed block 0x7f8c4a003200 for request 0x7f8c4a001b20, reason=completed每个block的分配和释放都有记录。如果发现某个block长时间没有被释放，那可能就是内存泄漏了。
3.3.2 内存使用统计
INFO 02-15 10:23:46 memory.py:200] GPU memory usage: 14.2GB/16.0GB (88.75%), cache usage: 8.1GB, kv_cache blocks: 512/640这个统计信息非常有用：
- GPU memory usage：总显存使用量
- cache usage：KV cache占用的显存
- kv_cache blocks：已使用的block数/总数
我的经验： 当GPU内存使用率超过90%时，建议立即检查是否有请求堆积。如果kv_cache blocks使用率接近100%，说明显存已经饱和，新的请求可能会被拒绝或触发抢占。
3.4 错误日志分类：快速定位问题
错误日志是排查问题的第一入口。vLLM的错误日志主要分为以下几类：
3.4.1 显存相关错误
ERROR 02-15 10:23:47 memory.py:300] CUDA out of memory. Tried to allocate 256MB for kv_cache block
ERROR 02-15 10:23:47 scheduler.py:400] Failed to allocate memory for request 0x7f8c4a001b20这类错误通常意味着显存不足。解决方案：
- 减少max_num_seqs或max_model_len
- 使用更小的模型
- 增加GPU数量
3.4.2 请求超时错误
WARNING 02-15 10:23:48 scheduler.py:450] Request 0x7f8c4a001b20 timed out after 30s
ERROR 02-15 10:23:48 api_server.py:200] Request timeout: 0x7f8c4a001b20请求超时通常是因为：
- 模型推理太慢（itl过高）
- 排队时间过长（waiting queue太大）
- 显存不足导致频繁抢占
3.4.3 模型加载错误
ERROR 02-15 10:23:40 model_loader.py:150] Failed to load model: FileNotFoundError: No such file or directory: '/models/llama-2-7b/pytorch_model.bin'这类错误通常出现在模型路径配置错误或模型文件损坏时。检查环境变量和模型路径即可。
3.4.4 通信错误（分布式场景）
ERROR 02-15 10:23:50 distributed.py:120] NCCL timeout: rank 2 failed to synchronize after 30s
ERROR 02-15 10:23:50 distributed.py:121] Possible causes: network congestion, GPU hang, or NCCL version mismatch分布式推理中，NCCL超时是最常见的错误之一。我曾经遇到过因为网络交换机故障导致某个节点通信超时，整个集群的推理任务全部失败。排查这类问题，建议先检查网络延迟和NCCL版本。
3.5 知识体系总览
为了让你更直观地理解这四种日志的关系，我画了一张图：
这张图把四种日志的关系和排查顺序都画出来了。我个人习惯的排查路径是：先看错误日志定位问题类型，再看内存日志确认资源状态，然后分析调度日志了解排队情况，最后用请求日志验证修复效果。
核心总结：
- 请求日志：关注ttft和itl，它们是性能的“体温计”
- 调度日志：关注抢占和队列长度，它们是系统压力的“晴雨表”
- GPU内存日志：关注block使用率和显存占比，它们是资源的“水位线”
- 错误日志：分类明确，按图索骥即可
日志解析这块，说白了就是多读、多练、多总结。刚开始可能会觉得眼花缭乱，但只要你坚持在生产环境里看上一周，这些日志就会像老朋友一样熟悉。