前言
我在家里用两张 GPU 跑本地 LLM,运营一个角色聊天服务。模型是 GLM-5.3-Flash 的 3bit GGUF,由 llama-server 以 4 个 slot 提供服务。
用户多起来以后,高峰时大约有 5 个人同时聊天。差不多从那时起,变慢的轮次开始明显起来。
按常理,对策不外乎这些:
- 减少输入 token(缩短历史,把图片换成文字说明)
- 提高并行数
- 增加 GPU
我们甚至写好了设计文档,首选方案是“保存角色图片时生成说明文字,对话时不再发送像素”。
先说结论:这些都不是正解。 服务器一天有 92% 的时间处于空闲,能力是够的。变慢的原因是,有人跑长 prefill 时,其他人的生成几乎停止。
而修复的第一步,只是改了一个启动选项。
这篇文章记录了得出这个结论的日志分析,以及途中猜错的假设。
文档里写了什么
最初的文档里,有这样一份 24 小时日志的统计。
| 统计对象 | 次数 | 中位数 | p95 | 最大 |
|---|---|---|---|---|
| 普通轮次 | 379 | 10.9 秒 | 59.9 秒 | 123.2 秒 |
| 其中缓存率 95% 以上 | 309 | 10.2 秒 | 42.4 秒 | 123.2 秒 |
| 其中未缓存 5,000 token 以上 | 32 | 36.3 秒 | 90.2 秒 | 98.7 秒 |
这份文档是和 Codex 一起写的,态度很严谨。它明确写着“不能断定 5 人同时使用或摘要就是原因”,结论是需要更多测量。
但仔细看这张表,有个奇怪的地方:缓存几乎全部命中,最长却要 123 秒。
输入没有重读,为什么要花两分钟?减少输入解释不了这一点。
逐个任务对照日志
在加新的测量之前,我决定先分解手头已有的日志。
llama-server 的日志为每个任务留下了这些信息:
slot launch_slot_: id 0 | task 789281 | processing task
slot print_timing: id 0 | task 789281 | n_gen = 159, tg = 52.63 t/s, tg_3s = 52.97 t/s
slot print_timing: id 0 | task 789281 | prompt eval time = 612.51 ms / 193 tokens
slot print_timing: id 0 | task 789281 | eval time = 3526.61 ms / 187 tokens
slot release: id 0 | task 789281 | stop processing: n_tokens = 20756
应用这边记录了每次调用的用途(普通轮次、摘要、翻译等)。按时间和输入 token 数把两者对应起来,854 个任务的开始、prefill、生成、结束就都排到了时间轴上。
顺便一提,我起初把日志时间 3517.09.125.958 读成了“时.分.秒.毫秒”,算出了 343 秒这个奇怪的中位数。正确的读法是“分.秒.毫秒.微秒”。
时间花在哪里
我假设单独运行的速度是生成 52 tok/s、prefill 800 tok/s,分解了聊天总处理时间 7,191 秒。
| 明细 | 秒 | 占比 |
|---|---|---|
| 自己的生成 | 3,481 | 48% |
| 与他人竞争造成的增量 | 2,535 | 35% |
| 自己的 prefill | 1,175 | 16% |
输出的中位数是 347 token,单独运行也要大约 7 秒。也就是说,“中位数的慢”大部分只是因为生成本身长。但是,慢轮次的长尾是竞争造成的。
不是原因的东西
逐一排查后,好几种看似合理的说法都被排除了。
| 假设 | 结果 |
|---|---|
| GPU 能力不足 | 服务器 92% 的时间空闲。两个以上任务同时运行约占一天的 2% |
| 5 个人抢 4 个 slot | 5 分钟内的 366 个连续轮次中,缓存未命中只有 3 次 |
| 后台处理碍事 | 约 300 个无日志任务合计约 450 秒,摘要 728 秒 |
| 上下文越长生成越慢 | 超过 1 万 token 后稳定在约 48 tok/s |
| 应用的并发上限 3 不够 | 闸门等待只有 2 次 |
slot 几乎没有被争抢,这让我很意外。llama-server 的内存提示词缓存确实发挥了作用。其实这个缓存不久前还经常未命中,相关调查写在另一篇文章里。
真正的瓶颈
决定性的是 tg_3s(最近 3 秒的生成速度)的比较。
| 自己生成时的情况 | tg_3s 中位数 |
|---|---|
| 与其他 slot 的 1.5 万 token 以上 prefill 重叠(59 个样本) | 0.34 tok/s |
| 其他情况(1,360 个样本) | 44.7 tok/s |
大约慢了 130 倍。 在屏幕上看,就是完全停住了。
原因在 tools/server/server-context.cpp 的 update_slots。一轮处理大致是这样:
- 把正在生成的 slot 的下一个 token 放入 batch
- 把正在 prefill 的 slot 的输入塞进 batch,直到
n_batch - 把 batch 处理完
- 到这时,正在生成的 slot 的下一个 token 才确定
n_batch 默认是 2048。prefill 约 800 tok/s,所以一轮大约 2.6 秒。正在生成的人每 2.6 秒才能前进 1 个 token。算下来约 0.39 tok/s,与实测的 0.34 相符。
GPU 时间大致与 batch 内的 token 数成正比,所以谁在一轮里塞得多,时间就归谁。
A:正在生成,B:2.5 万 token 的 prefill
第 1 轮:A 1 token + B 2047 tokens → 约 2.6 秒 → A 得到一个字
第 2 轮:A 1 token + B 2047 tokens → 约 2.6 秒 → A 得到一个字
……这样持续约 31 秒
那么长 prefill 从何而来?40 次 5,000 token 以上的 prefill,大多是下面两种。
| 来源 | 次数 | 新增 token 合计 |
|---|---|---|
| 当天的第一轮 | 21 | 33 万 |
| 刚应用历史摘要后的一轮 | 13 | 30 万 |
每当有人恢复对话,或长历史被折叠成摘要,就要重读 2 万 token 左右。本人等一下或许没办法,但每次其他所有人也都停了下来。
一个彻底猜错的假设
这里我自己的解释也错了一次。
我解释说“新来的短聊天要看 slot 编号的运气”,结果一数,编号在前是 8.5 秒,在后是 5.3 秒,并没有关系(各不到 10 例)。
重新看进度日志,短聊天的 prefill 也会在 checkpoint 边界分成几轮,而每一轮都被长 prefill 填满。有一轮新输入只有 12 token,却花了 10 秒。这是根据时间顺序作出的解释,但比 slot 编号合理得多。
另一个原因:指标看不到的等待
我一直把 prefill 时间当作“到第一个字的时间”,这也是错的。
有些任务的总时间远大于 prefill 加生成。一个任务总共 85.6 秒,prefill 只有 1.9 秒,生成 6.8 秒。剩下的 77 秒去哪了?
prefill 开始之前的等待,不计入 prompt eval time。 重新计算后,到第一个字的 p95 不是 19.2 秒,而是 29.2 秒。
我按等待期间在运行什么,对这些等待做了分类。
| 等待期间运行的任务 | 次数 | 等待合计 | 最大 |
|---|---|---|---|
| LoRA 设置不同的任务 | 40 | 540 秒 | 76.8 秒 |
| LoRA 设置相同的任务 | 4 | 40 秒 | 29.1 秒 |
| 没有其他任务 | 15 | 41 秒 | 18.6 秒 |
这个服务当时按请求切换 LoRA,只应用在部分轮次上。llama-server 不能把 LoRA 设置不同的 slot 放进同一个 batch(can_batch_with)。只要先选中的设置还在被处理,其他设置的请求甚至无法开始。
我之前的文档里写着“只有 4 个 slot,没有实际危害”。实际危害是有的。
修复 1:把 n_batch 改成 512
我最初想的对策是给 llama-server 打补丁,只在有 slot 正在生成时限制 prefill 的量。
但共同开发者(人类那位)提出:“如果 512 和 2047 相比对 prefill 影响不大,最坏的情况下全都用它。”这个主意好得多。
n_ubatch 默认是 512,所以现在的 2048 内部本来也是按 512 处理的。从日志的进度,还能得到不同 batch 大小的速度。
| 一次前进的 token 数 | prefill 速度 |
|---|---|
| 接近 2048 | 845 tok/s |
| 600〜1500 | 816 tok/s |
| 256〜600 | 719 tok/s |
| 64〜256 | 436 tok/s |
小 batch 多出现在刚创建 checkpoint 之后,所以数字应该偏低。我判断 512 对 prefill 的影响不大,加了一个环境变量。
[Service]
Environment=LLAMA_ARG_BATCH=512
应用后,我让 6,201 token 的 prefill 与生成重叠,测了一次。
| 项目 | 结果 |
|---|---|
| 生成速度(prefill 前 / 中 / 后) | 47.7 / 2.06 / 45.6 tok/s |
| prefill 期间的 token 间隔 | 中位数 0.44 秒,最大 1.54 秒 |
| prefill 速度 | 802 tok/s |
| 进度步长 | 511 tokens |
与单独运行的日志统计(845 tok/s)相比,prefill 只降了约 5%,而停住的生成恢复到了约 2 tok/s。不用打补丁,fork 的差异也没有增加。虽然还是断断续续,但“停住”和“慢”差别很大。
修复 2:统一 LoRA
对于 LoRA 造成的等待,我最初提议打补丁,每轮交替切换设置。这同样是没测量就提出的方案,一测量就被否决了。
趁线上模型空闲,我发了一些短请求作比较。
| 条件 | prefill 时间(中位数) |
|---|---|
| 连续不用 LoRA | 247 ms |
| 连续使用 LoRA | 273 ms |
| 刚切换到 LoRA | 1,008 ms |
| 刚切换到不用 LoRA | 995 ms |
切换一次约 0.74 秒。 读代码可知,LoRA 变化会设置 sched_need_reserve,下一次 decode 的 sched_reserve 会重建调度器,并预留三次计算图(内部明细没有直接测量)。
如果每轮交替,按计算两个人的生成各约 0.65 tok/s,和停住差不了多少。
这次又是人类那位说:“要么全用 LoRA,要么全不用,不是更好吗?”不是让切换更快,而是消除切换。 速度差也只有约 8.5%。
这个改动会改变输出内容,所以我按 scale 比较了日常对话、翻译、图片描述等,然后让几乎所有轮次都用同一设置。质量评价的细节不在本文范围内。
真实流量下的结果
我用同一个脚本,比较了改动前的 24 小时(11/5 03:20〜11/6 03:20)和两项改动都上线后的约 29 小时(11/6 07:57〜11/7 12:40)。
先看整体数字,确实变好了。但不能直接说这就是效果,因为改动后的使用量少了很多。
| 改动前 | 改动后 | |
|---|---|---|
| 聊天轮次 | 458(19 次/小时) | 315(11 次/小时) |
| 两个以上任务同时运行的时间 | 1,750 秒 | 414 秒 |
| 到第一个字的 p95(全部轮次) | 29.2 秒 | 19.5 秒 |
于是我只取拥挤程度相同的轮次重新比较。对象是新输入不到 1,000 token 的短轮次,它们本该马上开始。
| 到第一个字的时间(中位数 / p90) | 改动前 | 改动后 |
|---|---|---|
| 没有其他任务运行 | 1.4 / 2.5 秒(290 次) | 1.1 / 2.2 秒(223 次) |
| 与其他任务重叠 | 2.0 / 8.7 秒(71 次) | 1.3 / 1.7 秒(12 次) |
| 与 5,000 token 以上的 prefill 重叠 | 9.0 / 33.3 秒(20 次) | 2.3 / 3.1 秒(7 次) |
与长 prefill 重叠的轮次,最大值从 78.7 秒降到了 3.1 秒。各个原因对应的指标,也都按预期变化了。
| 指标 | 改动前 | 改动后 | 主要起作用的改动 |
|---|---|---|---|
| 1.5 万 token 以上 prefill 期间的生成速度(中位数) | 0.34 tok/s(58 个样本) | 1.62 tok/s(15 个样本) | n_batch |
| prefill 开始前 1 秒以上的等待 | 60 次,合计 632 秒,最大 76.8 秒 | 1 次,8 秒 | LoRA |
| 5,000 token 以上的 prefill 速度(中位数) | 824 tok/s | 830 tok/s | — |
| 生成速度(中位数) | 47.1 tok/s | 49.0 tok/s | — |
担心的 prefill 下降,在真实流量下没有出现。在这次比较中,也没有看到全部轮次使用 LoRA 带来的生成速度下降。不过其他条件混在其中,还不能说代价为零。
但现在还不能说问题解决了。
- 改动后的样本很少。 最想知道的那一行只有 7 次,也只有一天多的数据
- 最初引发这一切的拥挤没有再现。 改动后 4 个任务同时运行的时间只有 1 秒,5 人同时聊天的时段还没测到
n_batch和 LoRA 的效果分不开。 我在几小时内接连上线了这两项改动。设计文档明明写着“混在一起就分不清原因”,我却反着做了。上表的“主要起作用的改动”是根据机制作出的推断- 没有其他任务时的中位数也从 1.4 秒变成了 1.1 秒。这种程度的差异,与拥挤无关也会出现
没有采用的对策
我重新估算了最初的首选方案,也就是图片说明文字化的效果。
- 本地模型的角色最多 5 张图,每张 784 token,合计约 5 秒
- 图片只在冷启动时有成本,一天 27 次,有两张以上图片的角色约占 3 成
- 一天最多约 40 秒,约占全部聊天的 1%
缩短历史预算的方案,也只有一天约 90 秒。两者思路都不差,但效果不值得拿对话质量去换。
设计得最细致的方案,效果最差。
学到的东西
1. 看平均值之前,先看长尾里的矛盾。 “缓存命中却要 123 秒”这一行,从一开始就说明减少输入解释不了问题。
2. 增加测量之前,先对照已有的日志。 这次分析没有新增一行测量,需要的信息几乎都在日志里。
3. 确认指标没有测量什么。 prompt eval time 不包含等待。正因为这个盲区,LoRA 的问题才一直没被发现。
4. 数完之后,还要继续怀疑假设。 发现 0.34 tok/s 后,我又错误地归咎于“slot 编号的运气”,还在测量切换成本之前就推荐了交替方案。一旦数据说中一次,下一个解释也容易变得过于自信。
5. 让它变快之前,先想想能不能去掉它。 用设置值代替补丁,消除切换而不是加速切换。两个好主意都来自退一步看问题的提问。
让停住的生成动起来的竟然只是一个环境变量,有点不甘心,但非常开心。
想要复现的话
要在自己的环境里看,只需对照这些:
slot launch_slot_和slot release:任务的开始和结束prompt eval time/eval time:prefill 和生成的时间n_gen … tg_3s:生成的瞬时速度(100 token 之后,每 3 秒一次)总时间 - prompt eval - eval:prefill 开始前的等待
如果你的服务在多个 slot 上跑长 prefill,可以先看“与长 prefill 重叠区间的 tg_3s”。llama-server 的版本和配置不同,表现也会不同,这些数字请理解为来自 GLM-5.3-Flash 3bit、两张 GPU、4 个 slot、共享 KV 的环境。
