AIの応答が遅い原因を、ホスト起因とプロバイダ起因に分解 — 実測29,628件

2026年10月20日

LLM応答時間を firstbyte と body に分解し、ホスト起因とプロバイダ起因を切り分ける計測の概念図

「AIの応答が遅い」——その原因はホスト側にあるのか、プロバイダ側にあるのか。先に結論を書くと、遅さの約94%はプロバイダ側の本文生成であり、ホストの再起動では解消しない。25日分・29,628件を測っても、その構図は変わらなかった。

「再起動で速くなった気がする」を確かめる — AIの応答が遅い原因を測る

ある日、「ホストを再起動してから、エージェントの1ループあたりの所要時間が短くなった気がする。気のせいだろうか」という問いが飛んできた。体感をそのまま否定も肯定もできないので、ログから集計することにした。

体感を否定しないのは、否定する根拠がないからである。同時に、肯定する根拠もなかった。だから分けることにした。遅さがホスト側にあるのか、プロバイダ側にあるのかを。この切り分けができれば、「再起動を打つべきか、待つべきか」を判断できる。

最初の集計は2日分、2,303件だった。そこでの結論は「遅さの約94%はプロバイダ側の本文生成であり、再起動では解消しない」というものだった。だが2日分では、曜日や時間帯の偏りを排除できない。そこで観測を続け、25日分・29,628件まで積み上げて同じ集計をやり直した。結論は変わらなかった。むしろ、より強く出た。本稿はその記録である。計測対象であるエージェント基盤の全体像は私のAI環境の見取り図にまとめた。

なぜ既存ログから LLM 応答時間を分解できたのか

理想を言えば、計測したい場所に計測コードを入れるのが正しい。LLMクライアントの呼び出しに開始と終了の時刻を記録し、処理時間を構造化ログに出す。そうすれば分解は自明になる。

だが、その改修は今回の調査の範囲外だった。また、過去に遡って原因を調べたいときに、計測を足してからでは過去のデータが取れない。既にログに残っている情報だけで分解できるなら、そちらのほうが調査の初動として速い。

調べたところ、3つのイベントが既にログに残っていた。LLMクライアントは応答時間を明示的に記録していないため、それらを突き合わせて分解する方法を取った。

記号	ログ行	意味
A	リクエスト送出の行	呼び出し開始
B	httpx の HTTP Request 出力（200 OK）	応答ヘッダ受信
C	本文読了・解析完了の行	生成完了

この3点から、次の3つの指標を計算する。

firstbyte = B − A … 回線往復とTLS、プロバイダ側の初回トークン待ち
body = C − B … プロバイダの本文生成時間
llm_total = C − A … 呼び出し全体の所要時間

分解の狙いは、「遅さ」の中身を回線と生成に分けることにある。ホストの再起動で改善しうるのは firstbyte の側であり、body は再起動では変わらない。応答ヘッダが返るまでの時間は回線とホストの仕事であり、そのあとの本文生成はプロバイダの仕事である。責任分界がこの2点にある。

会話IDが無いログをどう対応付けたか

解析を難しくしたのは、ログに会話IDが付いていないことだった。複数の会話が並列で走ると、AとBとCが混ざる。どのAに対してどのBが対応するのかが、ログだけでは一意に決まらない。

そこで、呼び出しの順序を保ったまま「最古マッチ」で対応づけ、待ち時間の上限を600秒でキャップする近似を採用した。プロバイダの応答は通常数十秒で返るので、600秒を超えて開いたままの呼び出しは別物として扱う。

この近似の精度は、25日分・29,628件の対応付けで、対応先が見つからなかったものが27件だった。率にして0.09%である。実用上は十分と判断したが、厳密ではない。会話IDがログにあれば、この曖昧さは消える。

実測結果 — 応答時間の94%はプロバイダ側だった

対象期間は2026年9月25日0時から10月19日9時34分までの25日間、呼び出しは29,628件である。結果は次のとおりだった。

指標（秒）	p50	p90	p99	max	mean
firstbyte	0.588	0.757	0.989	8.600	0.612
body	9.215	32.354	97.362	588.556	15.319
llm_total	9.814	32.972	97.870	589.275	15.931

llm_total の中央値9.814秒のうち、body が9.215秒である。つまり呼び出し時間の約94%が本文生成に費やされている。平均で見るとその比率は96.2%まで上がる。裾の長い呼び出しがすべて body 側に集中しているためだ。

firstbyte は中央値0.588秒、p99でも0.989秒と極めて安定していた。25日間・約3万件を集計しても、p99が1秒を切っている。回線往復とTLS、初回トークン待ちはボトルネックになっていない。ばらつきの大きい body は、そのままプロバイダ側の生成時間の変動を反映している。

応答時間の分布 — 中央値10秒、p99は97秒

中央値だけを見ると「だいたい10秒」で落ち着いて見える。だが裾はかなり長い。body の p99 は97.4秒、最大は588.6秒である。1割の呼び出しが32秒以上かかっており、100回に1回は1分半近くかかる。2日分の集計では p99 が59.2秒だったので、観測期間を延ばしたことで、より長い裾が捉えられたことになる。

エージェントは1つの指示に対して何度もLLMを呼ぶ。1回あたりの中央値が10秒でも、20回呼べば合計は200秒になる。体感の「遅い」は、単発の最大値ではなく、この積み上がりから生まれる。だから平均だけでなくp90とp99を並べて見る必要がある。

平均が15.319秒で中央値が9.215秒という差も、裾の重さを示している。少数の極端に遅い呼び出しが平均を押し上げている。中央値だけを見て「10秒だ」と安心するのは、実際の体験と合わない。

日ごとの変動 — ホストは1.3倍、プロバイダは3.2倍

25日分を日単位で並べると、2つの層の性質の違いがはっきり出る。

firstbyte の日次中央値は 0.526秒（10月19日）から 0.680秒（10月6日）までの幅に収まる。最大と最小の比は 1.29倍。
body の日次中央値は 6.230秒（10月9日）から 19.612秒（9月28日）まで動く。比は 3.15倍。

ホストと回線を反映する firstbyte は、25日間を通じてほぼ一定である。プロバイダの生成時間を反映する body は、同じ25日間で3倍以上振れる。遅いと感じる日と速いと感じる日の差は、この body の振れで説明できる。

日次の body 中央値が高かったのは9月28日（19.6秒）、9月29日（16.3秒）、10月16日（14.3秒）、10月17日（14.4秒）である。逆に低かったのは10月9日（6.2秒）、10月5日（6.3秒）、10月18日（6.9秒）、10月4日（6.9秒）。同じホスト、同じ回線、同じコードで、これだけ動く。ホスト側の設定をいじっても、この振れは変わらない。

ホスト側は健全だった — firstbyte は25日間ほぼ一定

同時点でホスト側の状態も実測した。

指標	実測値
load average	0.73 / 0.81 / 0.62
メモリ	16GB中 8.4GB使用 / 7.6GB available
swap	5,428MB / 8GB（zram 7.8G 有効、5.3G使用）
プロバイダRTT	平均 11.2ms（パケットロス 0%）
DNS / connect / TLS	0.8ms / 6.7ms / 16.1ms
HTTP TTFB（認証エラー応答）	約 0.22秒

負荷は低く、メモリに余裕がある。回線の往復遅延も、最小4.5ms・平均11.2ms・最大36.6msの範囲で安定していた。ホストが原因で遅くなっている兆候は見当たらない。

DNS・connect・TLSを合計しても24ms程度である。firstbyteの0.59秒のうち、大半は回線の往復ではなく、プロバイダ側がリクエストを受理して処理を始めるまでの待ち時間ということになる。仮にホスト側のDNSやTLSを最適化して数ms削れたとしても、0.59秒のうちの数msである。体感は変わらない。

再起動3回の前後比較 — 効くのはホスト起因の遅さだけ

25日間のうち、ホストの再起動は3回あった。9月26日11時12分、9月30日9時27分、10月10日15時57分である。それぞれの前後で集計を分けた。

再起動	区分	n	firstbyte p50	body p50	llm_total p50
09-26 11:12	前	1,217	0.605	8.268	8.926
09-26 11:12	後	1,086	0.595	10.650	11.284
09-30 09:27	前	1,518	0.591	15.868	16.407
09-30 09:27	後	215	0.555	10.620	11.185
10-10 15:57	前	1,282	0.605	8.833	9.408
10-10 15:57	後	1,725	0.624	7.193	7.884

firstbyte は3回ともほとんど変わっていない。0.555秒から0.624秒の範囲で、誤差の範囲である。ホストと回線が前後で変化していないことを裏づけている。

body は回によって下がったり上がったりしている。9月30日は15.87秒から10.62秒へ下がったが、9月26日は8.27秒から10.65秒へ上がった。10月10日は8.83秒から7.19秒へ下がった。3回のうち2回は下がり、1回は上がった。方向が揃っていない。

この不一致そのものが結論である。もし再起動がプロバイダ起因の遅さに効くなら、3回とも同じ方向に動くはずだ。揃わないのは、再起動の効果ではなく、その時々のプロバイダの混雑を拾っているからである。firstbyteが3回とも変わらなかったことは、ホスト側に改善の余地がなかったことを示している。

再起動の前後比較には、交絡がある。再起動した時刻の前後で、プロバイダの混雑度が違う可能性がある。9月30日の再起動は朝9時27分で、直前の夜間から早朝にかけては body が伸びやすい時間帯だった。だから「再起動後に速くなった」ように見える。

今回のデータでは、firstbyteが前後で変わらなかったことが1つの手がかりになる。ホスト側の処理が変わっていないなら、bodyの変化はホストの再起動では説明できない。消去法でプロバイダ側の要因が残る。

より厳密にやるなら、同じ時間帯どうしを比べる。あるいは複数日の同一時刻のデータを並べる。25日分あれば、時間帯ごとのベースラインを引くことは可能になった。次段の課題である。

分解して分かったこと — 再起動が効く条件と判断基準

この分解から得られる実務的な結論は明快である。再起動が効くのはホスト起因の遅さのときだけで、プロバイダ起因の遅さには効かない。なお、ホストを止めずに更新する仕組みそのものはAIエージェント基盤を止めずに更新するに書いた。今回の実測では、遅さの94%がプロバイダ起因だった。したがって、体感で「遅い」と感じたときにホストを再起動しても、多くの場合は改善しない。

逆に言えば、firstbyte が伸びているかどうかを見れば、再起動という手段を打つべきかを判断できる。firstbyte が平常（0.6秒前後）で body だけが伸びているなら、待つか、プロバイダを替えるか、プロンプトや出力長を見直すかの話になる。

25日分のデータは、この判断基準に具体性を与える。firstbyteの日次中央値は0.53秒から0.68秒の間に収まる。したがって、firstbyteが1秒を超えて伸びている日があれば、それは通常の変動ではなく、ホストか回線に何かが起きている合図になる。逆に、firstbyteが0.6秒のまま body だけが20秒に伸びているなら、ホストを触っても無駄である。

「遅い」という1つの体感を、2つの原因に分けて見えるようにしたことが、今回の成果だと考えている。さらに、その境界値が25日分の実測で裏づけられたことで、判断は勘ではなく基準で行えるようになった。

次にやること — 応答時間の定点観測と、この計測の限界

分解のロジックは毎日回せる形にした。次はこれを定点観測にして、firstbyte と body と llm_total の時系列を中央値とp90で描き、再起動の時点をマーカーとして重ねる。これにより、「今はどの層が伸びているのか」を一目で見られるようにしたい。

グラフは2段に分ける。上段に firstbyte、下段に body を置く。上段が跳ねればホストか回線、下段が跳ねればプロバイダである。再起動のマーカーは上段に効いて下段には効かない、という関係が絵で見えるはずだ。25日分のデータでは、上段がほぼ水平で下段だけが3倍振れるという構図が既に数字で出ている。これを絵にすれば、判断はさらに速くなる。

最終的にはダッシュボードに載せ、遅いと感じたときに原因の層を見てから対応を決める、という運用にしたいと考えている。感覚で再起動するのをやめ、計測してから打つ、という順序に変えるのが狙いである。

ダッシュボードは既存の監視基盤に相乗りする形で置く。この監視基盤で障害の初動を自動化した話はアラート一次調査の自動化にまとめている。CPUやメモリのグラフと同じ画面に、firstbyte と body が並ぶ。遅いと感じたときに開く画面を1つにしておけば、「ホストか、プロバイダか」をその場で判断できる。