Kotonia
登录立即开始

Kotonia Articles

5 人同时用就变慢,并不是能力不足:对照 llama-server 日志发现,生成停到了 0.34 tok/s

同时使用时变慢并不是 GPU 不够。对照 llama-server 日志发现,长 prefill 期间其他人的生成停到了 0.34 tok/s。记录从定位原因到线上验证的全过程。

作者 6分钟阅读
#llm#llamacpp#gpu#性能优化#个人开发

前言

我在家里用两张 GPU 跑本地 LLM,运营一个角色聊天服务。模型是 GLM-5.3-Flash 的 3bit GGUF,由 llama-server 以 4 个 slot 提供服务。

用户多起来以后,高峰时大约有 5 个人同时聊天。差不多从那时起,变慢的轮次开始明显起来。

按常理,对策不外乎这些:

  • 减少输入 token(缩短历史,把图片换成文字说明)
  • 提高并行数
  • 增加 GPU

我们甚至写好了设计文档,首选方案是“保存角色图片时生成说明文字,对话时不再发送像素”。

先说结论:这些都不是正解。 服务器一天有 92% 的时间处于空闲,能力是够的。变慢的原因是,有人跑长 prefill 时,其他人的生成几乎停止。

而修复的第一步,只是改了一个启动选项。

这篇文章记录了得出这个结论的日志分析,以及途中猜错的假设。


文档里写了什么

最初的文档里,有这样一份 24 小时日志的统计。

统计对象次数中位数p95最大
普通轮次37910.9 秒59.9 秒123.2 秒
其中缓存率 95% 以上30910.2 秒42.4 秒123.2 秒
其中未缓存 5,000 token 以上3236.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,48148%
与他人竞争造成的增量2,53535%
自己的 prefill1,17516%

输出的中位数是 347 token,单独运行也要大约 7 秒。也就是说,“中位数的慢”大部分只是因为生成本身长。但是,慢轮次的长尾是竞争造成的。

不是原因的东西

逐一排查后,好几种看似合理的说法都被排除了。

假设结果
GPU 能力不足服务器 92% 的时间空闲。两个以上任务同时运行约占一天的 2%
5 个人抢 4 个 slot5 分钟内的 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。一轮处理大致是这样:

  1. 把正在生成的 slot 的下一个 token 放入 batch
  2. 把正在 prefill 的 slot 的输入塞进 batch,直到 n_batch
  3. 把 batch 处理完
  4. 到这时,正在生成的 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 合计
当天的第一轮2133 万
刚应用历史摘要后的一轮1330 万

每当有人恢复对话,或长历史被折叠成摘要,就要重读 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 设置不同的任务40540 秒76.8 秒
LoRA 设置相同的任务440 秒29.1 秒
没有其他任务1541 秒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 速度
接近 2048845 tok/s
600〜1500816 tok/s
256〜600719 tok/s
64〜256436 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 时间(中位数)
连续不用 LoRA247 ms
连续使用 LoRA273 ms
刚切换到 LoRA1,008 ms
刚切换到不用 LoRA995 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/s830 tok/s—
生成速度(中位数)47.1 tok/s49.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 的环境。

Kotonia 将语音 AI、AI 聊天、图像生成和团队协作整合到一个 AI 工作区中。

试用 Kotonia