Kotonia Articles

5人同時で遅いのは能力不足じゃなかった——llama-serverのログを突き合わせたら、生成が0.34 tok/sまで止まっていた

同時利用で遅いのはGPU不足ではなかった。llama-serverのログを突き合わせると、長いprefillの間、他の人の生成が0.34 tok/sまで止まっていた。原因の特定から、設定変更後の本番での検証までの記録。

著者清水真二2026-11-078分で読める

#llm#llamacpp#gpu#パフォーマンス#個人開発

他の言語英語中国語

はじめに

自宅のGPU 2枚でローカルLLMを動かして、キャラクターチャットのサービスを運営している。モデルはGLM-5.3-Flashの3bit GGUFで、llama-serverの4スロット構成だ。

利用者が増えて、同時に話す人が多いときで5人くらいになってきた。そのあたりから遅いターンが目立つようになった。

普通に考えると、対策の候補はこのあたりだ。

入力トークンを減らす（履歴を短くする、画像をキャプションに置き換える）
並列数を増やす
GPUを増やす

実際に設計資料まで作っていて、本命は「ペルソナ画像を保存時にキャプション化して、会話では画素を送らない」だった。

先に結論を書くと、どれも本命ではなかった。 サーバーは1日の92%が待機中で、能力は足りていた。遅い原因は、誰かの長いprefillが走っている間、他の人の生成がほぼ止まることだった。

そして修正の第一歩は、起動オプションを1つ変えるだけだった。

この記事は、そこに至るまでのログの分析と、途中で私たちが外した仮説の記録だ。

資料が言っていたこと

最初の資料には、24時間分のログからこんな集計があった。

集計対象	件数	中央値	95%点	最大
通常ターン	379	10.9秒	59.9秒	123.2秒
うちキャッシュ率95%以上	309	10.2秒	42.4秒	123.2秒
うち未キャッシュ5,000 tokens以上	32	36.3秒	90.2秒	98.7秒

資料はCodexと一緒に作ったもので、とても誠実だった。「5人同時利用や要約だけを原因と断定することはできない」とはっきり書いてあり、追加の計測が必要だと結論していた。

ただ、この表をよく見ると変なところがある。キャッシュがほぼ全部当たっているのに、最大123秒かかっている。

入力を読み直していないのに、なぜ2分もかかるのか。入力を減らす対策では、ここは説明できない。

ログを1タスクずつ突き合わせる

追加の計測を仕込む前に、今あるログで分解してみることにした。

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

アプリ側には、呼び出しの目的（通常ターン、要約、翻訳など）を記録した行がある。この2つを時刻と入力トークン数で突き合わせると、854タスクの開始、prefill、生成、終了が時間軸に並ぶ。

ちなみに最初は、ログの時刻 3517.09.125.958 を「時.分.秒.ミリ秒」と読んでしまい、中央値343秒という変な数字を出した。正しくは「分.秒.ミリ秒.マイクロ秒」だ。

何に時間を使っているか

チャットの合計処理時間7,191秒を、単独で動いたときの速度（生成52 tok/s、prefill 800 tok/s）を仮定して分解した。

内訳	秒	割合
自分の生成	3,481	48%
他との競合による増分	2,535	35%
自分のprefill	1,175	16%

出力の中央値は347 tokensで、単独でも約7秒かかる。つまり「中央値の遅さ」の大半は単に生成の長さだ。一方で、遅いターンの裾には競合が効いている。

原因ではなかったもの

順番に潰していくと、もっともらしい説がいくつも消えた。

仮説	結果
GPUの能力不足	サーバーは92%待機。2本以上の同時実行は1日の約2%
5人に4スロットで奪い合い	5分以内の連続ターン366件で、キャッシュ外れは3件
裏方の処理が邪魔	ログのない約300タスクは合計約450秒、要約は728秒
文脈が長いと生成が遅い	1万tokensを超えると約48 tok/sで横ばい
アプリ側の並列数が3で足りない	ゲート待ちは2件だけ

スロットの奪い合いがほぼ起きていなかったのは意外だった。llama-serverのRAMプロンプトキャッシュが、きちんと効いていたわけだ。実はこのキャッシュも少し前まではよく外れていて、その調査は別の記事に書いた。

本当のボトルネック

決定的だったのは、tg_3s（直近3秒の生成速度）の比較だ。

自分の生成中の状況	`tg_3s` 中央値
他のスロットの15K tokens以上のprefillと重なる（59サンプル）	0.34 tok/s
それ以外（1,360サンプル）	44.7 tok/s

約130分の1。 画面上では完全に止まって見える速さだ。

原因は tools/server/server-context.cpp の update_slots にある。1周の処理はだいたいこうなっている。

生成中のスロットの次の1トークンをbatchに入れる
prefill中のスロットの入力を、batchが n_batch になるまで詰める
batchを最後まで処理する
ここで初めて、生成中のスロットの次のトークンが決まる

n_batch の既定は2048だ。prefillが約800 tok/sなので、1周に約2.6秒かかる。つまり生成中の人は2.6秒に1トークンしか進めない。計算すると約0.39 tok/sで、実測の0.34と合う。

GPU時間はbatch内のトークン数にほぼ比例するので、1周に多く詰めた側が時間を持っていく。

A: 生成中、B: 25K tokensのprefill

1周目: A 1 token + B 2047 tokens → 約2.6秒 → Aに1文字分
2周目: A 1 token + B 2047 tokens → 約2.6秒 → Aに1文字分
……これが約31秒続く

では、長いprefillはどこから来るのか。5,000 tokens以上のprefill 40回の大半は次の2つだった。

発生源	回数	新規tokens合計
その日最初のターン	21	33万
履歴の要約を反映した直後のターン	13	30万

会話を再開したり、長い履歴を要約で畳んだりするたびに、20K tokens級の読み直しが走る。本人の待ちは仕方ないとしても、そのたびに他の全員が止まっていたわけだ。

仮説はきれいに外れた

ここで、自分の説明を一度外している。

「新しく来た短いチャットは、スロット番号の順番の運で待たされる」と説明したのだが、数えたら番号が先でも8.5秒、後でも5.3秒で、関係がなかった（各10件未満）。

進捗ログを見直すと、短いチャットのprefillもチェックポイントの境界で数周に分かれ、その各周が長いprefillで埋まっていた。新規入力12トークンのターンに10秒かかった例もある。時間の並びからの解釈だが、スロット番号よりはずっと合う。

もう1つの原因: 計器に映らない待ち

prefillの時間を「最初の文字まで」と読んでいたが、これも間違いだった。

タスクの中に、総時間 ≫ prefill + 生成 のものが混ざっていた。総時間85.6秒に対して、prefill 1.9秒と生成6.8秒しかない。残りの77秒はどこに消えたのか。

prefillが始まる前の待ちは、prompt eval time に入らない。 計算し直すと、最初の文字までの95%点は19.2秒ではなく29.2秒だった。

この待ちを、待っている間に何が走っていたかで分類した。

待っている間に走っていたもの	件数	待ち合計	最大
別のLoRA設定のタスク	40	540秒	76.8秒
同じLoRA設定のタスク	4	40秒	29.1秒
他に何もなし	15	41秒	18.6秒

このサービスでは、リクエスト単位でLoRAを切り替えて、一部のターンだけに当てていた。llama-serverはLoRA設定が違うスロットを同じbatchに入れられない（can_batch_with）。先に選ばれた設定が処理され続けると、別の設定のリクエストは始まることすらできない。

以前の自分の資料には「4スロットなので実害なし」と書いてあった。実害はあった。

修正1: `n_batch` を512にする

対策としてまず考えたのは、llama-serverにパッチを当てて、生成中のスロットがあるときだけprefillの量を絞ることだった。

ところが共同開発者（人間のほう）から、「512が2047と比べてprefillに大きな影響がないなら、最悪全部それにする」という案が出た。こちらのほうがずっと良かった。

n_ubatch の既定は512なので、今の2048も内部では512ずつ処理している。ログの進み方から、batchサイズごとの速度も取れた。

1回に進んだtoken数	prefill速度
ほぼ2048	845 tok/s
600〜1500	816 tok/s
256〜600	719 tok/s
64〜256	436 tok/s

小さいbatchはチェックポイント作成の直後に多いので、低めに出ているはずだ。512ならprefillの低下は小さいと読んで、環境変数を1つ足した。

[Service]
Environment=LLAMA_ARG_BATCH=512

適用して、6,201 tokensのprefillを生成に重ねて測った（1回だけ）。

項目	結果
生成速度（prefillの前 / 中 / 後）	47.7 / 2.06 / 45.6 tok/s
prefill中のトークン間隔	中央値0.44秒、最大1.54秒
prefill速度	802 tok/s
進捗の刻み	511 tokens

prefillの低下は単独時のログ集計（845 tok/s）と比べて5%程度で、止まっていた生成は約2 tok/sまで動くようになった。パッチなしで済み、forkの差分も増えない。まだ飛び飛びだが、「止まっている」と「遅い」はかなり違う。

修正2: LoRAを揃える

LoRA違いの待ちには、最初「周ごとに設定を交代させるパッチ」を提案した。これも測る前に言ってしまった案で、測ったら却下になった。

本番モデルが空いているときに、短いリクエストを流して比べた。

条件	prefill時間（中央値）
LoRAなしの連続	247 ms
LoRAありの連続	273 ms
LoRAありへ切り替え直後	1,008 ms
LoRAなしへ切り替え直後	995 ms

切り替え1回で約0.74秒。 コードを読むと、LoRAが変わると sched_need_reserve が立ち、次のdecodeで sched_reserve がスケジューラを作り直してグラフを3回予約する（内訳は直接測っていない）。

周ごとに交代すると、2人の生成は各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回/時）
2本以上が同時に動いていた時間	1,750秒	414秒
最初の文字まで p95（全ターン）	29.2秒	19.5秒

そこで、同じ混み具合のターンだけで比べ直した。対象は新規入力1,000トークン未満の短いターンで、本来ならすぐ始まるはずのものだ。

最初の文字まで（中央値 / p90）	変更前	変更後
他に何も動いていない	1.4 / 2.5秒（290件）	1.1 / 2.2秒（223件）
他のタスクと重なった	2.0 / 8.7秒（71件）	1.3 / 1.7秒（12件）
5,000トークン以上のprefillと重なった	9.0 / 33.3秒（20件）	2.3 / 3.1秒（7件）

長いprefillと重なったターンの最大は78.7秒から3.1秒になった。原因ごとの指標も、それぞれ想定どおりに動いている。

指標	変更前	変更後	主に効いた変更
15Kトークン以上のprefill中の生成速度（中央値）	0.34 tok/s（58サンプル）	1.62 tok/s（15サンプル）	`n_batch`
prefill開始前の1秒以上の待ち	60件、計632秒、最大76.8秒	1件、8秒	LoRA
5,000トークン以上のprefill速度（中央値）	824 tok/s	830 tok/s	—
生成速度（中央値）	47.1 tok/s	49.0 tok/s	—

心配していたprefillの低下は、実トラフィックでは見えなかった。LoRAを全ターンに当てた分の生成速度の低下も、この比較では見えていない。別の条件が混ざっているので、「コストがゼロ」とまでは言えない。

ただ、これで解決とはまだ言えない。

変更後のサンプルが少ない。 一番知りたい行が7件だけで、1日ちょっとの結果だ
最初のきっかけだった混雑は再現していない。 4本同時の時間は変更後は1秒だけで、5人が同時に話す時間帯は測れていない
n_batch とLoRAの効果は分けられない。 数時間のうちに続けて入れてしまったからだ。設計資料には「混ぜると原因が分からなくなる」と書いてあったのに、その逆をやっている。上の表の「主に効いた変更」は、仕組みからの推定だ
他に何も動いていないときの中央値も1.4秒から1.1秒に動いている。この程度の差は、混雑と関係なく出る

採らなかった対策

最初の本命だった画像キャプション化の効果を、見積もり直した。

ローカルモデルのペルソナは最大5枚で、1枚784 tokens。全部で約5秒
画像代がかかるのはcold時だけで、1日27回。2枚以上のペルソナは約3割
1日あたり多くても約40秒。チャット全体の約1%

履歴の予算を短くする案も、1日約90秒だった。どちらも筋は悪くないが、会話の品質と引き換えにするほどの効果はなかった。

一番丁寧に設計した案が、一番効かなかった。

学んだこと

1. 平均を見る前に、裾の矛盾を見る。 「キャッシュが当たっているのに123秒」という1行が、入力削減では説明できないことを最初から示していた。

2. 追加の計測の前に、今のログを突き合わせる。 今回の分析に新しい計測は1行も足していない。必要なものはほとんどログにあった。

3. 計器が何を測っていないかを確かめる。 prompt eval time は待ちを含まない。この計測の穴のせいで、LoRAの問題が見えていなかった。

4. 数えたあとも仮説を疑う。 0.34 tok/sを見つけたあとで「スロット番号の運」と外し、切り替えコストを測る前に交代案を勧めた。データを1つ当てると、次の説明にも自信が乗ってしまう。

5. 速くする前に、なくせないかを考える。 パッチより設定値、切り替えの高速化より切り替えの廃止。良い案はどちらも、問題を一段引いて見た質問から出た。

止まっていた生成を動かしたのが環境変数1つだったのは、少し悔しくて、かなり嬉しい。

再現したい人へ

自分の環境で見るなら、次を突き合わせるだけで同じ分析ができる。

slot launch_slot_ と slot release: タスクの開始と終了
prompt eval time / eval time: prefillと生成の時間
n_gen … tg_3s: 生成の瞬間速度（100トークン以降、3秒ごと）
総時間 - prompt eval - eval: prefillが始まる前の待ち

複数スロットで長いprefillが走るサービスなら、まず「長いprefillと重なった区間の tg_3s」を見てみるといい。llama-serverの版と構成で挙動は変わるので、この記事の数字はGLM-5.3-Flash 3bit、2GPU、4スロット、共有KVの環境のものとして読んでほしい。