Claude Code の初回応答を16秒から10秒に縮め、フリーズを0件にした — プロファイラで四つの無駄を解体した記録
はじめに
自分用のAIコーディングアシスタントには、以前ここに書いた仕組みを組み込んである。会話の入力を毎回捕まえて、今の話題に効きそうな過去の記録を自動で差し込む「活性化層」だ。
AIに毎ターン「今、思い出すべきこと」を差し込む — 個人RAGの活性化層
便利だが、これはAIが応答を書き始める前に、毎回必ず通る関所でもある。関所に無駄があれば、それは初回応答の遅さとしてそのまま返ってくる。
しばらく使っていて、二つの違う症状に気づいた。一つは「なんとなく遅い」という緩やかな体感。もう一つは、入力してから何分経っても何も返らず、停止操作すら効かないという、質の違う症状だった。この記事は後者を「遅い」の一言でまとめず、プロファイラで内訳を取って、四つの具体的な原因に分解し、実測で潰すまでの記録だ。
「遅い」を測れる形にする
体感の「遅い」をそのまま追いかけると、どこにでも寄り道できてしまう。実際、最初の調査は「AIが確認のために選択肢を出し、人間の返答を待っている時間」を測ることに寄り道した。これは人間待ちの時間であって、アシスタント自身の遅さではない。
寄り道に気づいた時点で、指標を一つに絞り直した。
A-2: ユーザーが入力を送信してから、AIの最初の出力が返るまでの秒数（中央値）。
測り方も固定した。セッションの記録（JSON Lines形式のログ）を走査し、「ユーザーの発言」レコードのタイムスタンプから、直後の「アシスタントの応答」レコードのタイムスタンプまでの差を取る。600秒を超えるものは離席の可能性があるため、通常の中央値計算からは除外し、別枠で数える。
この定義を先に固定してから、「何がどうなれば解決と言えるか」をチェックリストに書いた。afterの実測を取るところまでをワンセットにする——これを飛ばして「改善したはず」で止めないための、後で自分を検証するための約束事だ。
内訳を取る — プロファイラの出力
指標が決まれば、次は「何が16秒を食っているか」を測る番だ。検索処理そのものにPythonの標準プロファイラ（cProfile）をかけ、累積時間の内訳を取った。ウォームアップ後の1回の呼び出しで、合計約34.8秒。
| 区間 | 累積時間（cProfile下の1回） | 比率 |
|---|---|---|
| 関連度判定器への問い合わせ | 22.27 s | 64% |
| 検索結果の並べ替え（多様化） | 9.29 s | 27% |
| 埋め込み計算（うち接続確立 2.042 s） | 2.08 s | 6% |
| スコア計算 | 0.82 s | 2% |
この表の数字は、すべて「プロファイラをかけた状態での1回の呼び出し」の値だ。この後に出てくる「27.399秒」は同じ処理の別の計測（件数を120件に固定した専用のベンチマーク）の値で、条件が違うので直接は比べられない。同じ処理名に違う秒数が出てきたら、まず計測条件が同じかを疑う。
「関連度判定器」は、検索で取れたものの中から本当に関係あるものだけを絞り込む小さなモデルで、これも以前記事にした。
RAGに「関係あるか」を見分ける小さな判定器を置く — 取得したものを、全部は渡さない
「検索結果の並べ替え（多様化）」は、似た記録ばかりが上位を占めないように結果を並べ替える処理（MMR）で、検索の作り込み自体は別記事で書いた測定駆動チューニングの延長にある。
ベクトル検索だけのRAGは「肝心なときに思い出さない」— ハイブリッド検索＋測定で recall を 0.2→1.0 にした話
この内訳を図にすると、初回応答までに実際に何を待っていたかが見える。
ユーザーが送信
│
▼
[毎ターン必ず通る関所（活性化層フック）]
│
├─▶ 検索クライアントの起動
│ import に 2.409 s
│ HTTPクライアント生成に 1.337 s
│ └─ うちSSL証明書の読み込みだけで 0.958 s ◀── 平文HTTP通信なのに不要だった
│ （合計 毎ターン約 3.7 s）
│
├─▶ 検索結果の並べ替え（多様化・MMR）
│ 並べ替え処理に 9.29 s ◀── 件数の2乗に比例する実装だった
│ └─ 件数120件に固定した専用計測では 27.399 s（条件が違う別の数字）
│
├─▶ 関連度判定器への問い合わせ
│ 起動に失敗しても気づかず 22〜60 s 消費 ◀── cProfile内訳の64%
│ └── 失敗を2回連続で検知したら回路を開き、以後は即座に素通り
│ └────────────── 1,800 s 後に1回だけ再試行 ─────┘
│
▼
AIの最初の出力
縦の流れが「送信から初回応答まで」、横の分岐が「関所の中で並行に効いていた四つの無駄」、一番下の入れ子が「判定器の失敗を検知して以後は迂回する」ループになっている。
見つかった四つの無駄、潰した後
四つとも、内訳の数字を根拠に一つずつ潰した。
| # | 内容 | before | after |
|---|---|---|---|
| 1 | 検索結果の並べ替え（多様化）を、行列演算ライブラリ（numpy）を使う実装に置き換え | 27.399 s（入力120件に固定した専用計測） | 0.009 s（同じ120件・同条件。旧実装との突き合わせ15項目すべて一致） |
| 2 | 埋め込みサーバーへの接続先をlocalhostから127.0.0.1に固定 | 接続確立だけで 2.042 s | ほぼ 0 |
| 3 | 関連度判定器にサーキットブレーカーを実装 | 起動失敗のたびに気づかず 22〜60 s 消費 | 2回連続の失敗で回路を開き、以後は即座に素通り（1,800秒後に1回だけ再試行） |
| 4 | 関所のフックが検索クライアントを生成する方式を、標準ライブラリで直接HTTP通信する軽量な実装に変更 | import 2.409 s ＋ クライアント生成 1.337 s（うちSSL証明書読み込みだけで 0.958 s）＝毎ターン約 3.7 s | 毎ターン約 3.1 s 削減 |
原因2の「接続先を固定する」は地味だが理由がある。localhostという名前を解決すると、環境によってはIPv6アドレスへの接続を先に試して失敗し、そこからIPv4に切り替わるまでの分だけ待たされる。名前解決を挟まず、最初から使うアドレスを直接指定すれば、この待ちは丸ごと消える。
原因4のSSL証明書読み込みは、それ自体が無駄というより「そもそも要らない処理を律儀にやっていた」に近い。検索サーバーとの通信は平文HTTPで、暗号化していない。にもかかわらず、汎用のクライアントライブラリを使っていたせいで、TLS用の証明書一式を毎回読み込んでいた。使わない鍵束を毎回持ち歩いていたようなものだ。
4つのうち2つは、実装をまるごと別物に差し替える変更だった。どちらも、旧実装と同じ入出力を返すことを先に確認してから切り替えている。#1（並べ替えのnumpy化）は15項目——順序の一致を件数4通りで確認したうえで、空リスト・1件だけ・全ベクトルが同一（同点タイ）・ゼロベクトル・負の相関といった境界条件を並べたもの。#4（軽量クライアントへの差し替え）は24項目——埋め込みの値が旧実装と完全に一致すること（最大絶対差 0）と、正常系・異常系それぞれの分類結果が一致することを確認したものだ。数字を良くする変更ほど、先に壊していないことを確認してから入れる。
潰したはずなのに、変化が見えなかった一日
四つのうち最初の二つ（並べ替えの高速化・接続先の固定）を投入した当日、A-2の指標を測り直した。過去2週間、13日間の通常運用（n=680）の中央値は16.04秒。当日の中央値は15.85秒。ほとんど動いていない。
一見、効果が無かったように見える。ここで「効いていない」と結論しかけたが、測り方そのものを疑い直した。
集計の粒度を変えたら、結論が覆った
日単位の中央値は、同じ日の中に「修正が入る前のやり取り」と「入った後のやり取り」を混ぜて平均してしまう。 当日は四つの修正を段階的に投入していたので、日単位の集計では改善が薄まって見えなくなっていた。
そこで、修正コミットが実際に投入された時刻で当日を区切り直し、区間ごとにA-2を測り直した。
当日（1日分のログ）
00:00 ────────────────────────────────────────── 24:00
│ │ │ │
修正なし #1・#2投入 #3投入 #4投入（すべて反映）
(15.68 s) 01:31 09:22 14:07
│ │ │
▼ ▼ ▼
12.03 s 14.18 s 10.48 s ★
「日単位の中央値だけを見る」と、この4区間が一つの平均(15.85 s)に均され、
改善が見えなくなっていた。
| 区間 | 反映済みの修正 | n | 中央値 | p75 | p90 |
|---|---|---|---|---|---|
| 通常運用（13日間） | なし | 680 | 16.04 s | 26.93 | 41.10 |
| 当日 00:00〜01:31 | なし | 14 | 15.68 s | 21.97 | 31.05 |
| 当日 01:31〜09:22 | #1・#2 | 8 | 12.03 s | 15.91 | 29.38 |
| 当日 09:22〜14:07 | #1・#2・#3 | 34 | 14.18 s | 22.09 | 35.58 |
| 当日 14:07〜 | #1〜#4 すべて | 19 | 10.48 s | 11.63 | 31.14 |
通常運用の16.04秒から、四つすべてが揃った区間の10.48秒まで、中央値で−35%、p75（遅い方から4分の1の境目）では26.93秒から11.63秒で−57%。p75の下がり幅が中央値より大きいのは、四つの修正が「たまに大きく遅れるケース」により強く効いていたことを示している。
そしてもう一つ、A-2の集計からは外していた「600秒（10分）を超える完全な無応答」の件数を数え直した。
| 日 | 600秒超の件数 | 最大 |
|---|---|---|
| 08-11 | 7 | 828.0 s |
| 08-12 | 2 | 728.9 s |
| 08-21 | 1 | 612.5 s |
| 08-22 | 3 | 645.7 s |
| 08-23 | 7 | 971.3 s |
| 当日 | 0 | — |
過去2週間はほぼ毎日のように発生していた10分超の無応答が、四つの修正を入れた当日はゼロだった。「なんとなく遅い」の正体は主にこの関所の中の無駄だったが、「完全に停止する」の方は、そのうちの一つ（関連度判定器の起動失敗を毎回律儀に待っていたこと）が主犯だった可能性が高い。
ただし、この当日区間はn=19と小さく、しかも同じ一続きの作業時間からのサンプルに偏っている。600秒超の消失も1日分の観測にすぎない。実際、AIコーディングアシスタントの無応答は、この関所とは別の経路（並行して起動した子タスクの応答待ちなど）でも起きた実績があり、今回の四つの修正がそちら側まで塞いだわけではない。改善したとは言えるが、直したのはこの関所の中の一部というのが正確なところで、次にログを追う時はn を増やして確かめる必要がある。
副産物 — 検査する仕組み自身が、自分を誤検知した
四つの修正とは別に、もう一つ手を入れた。「接続先のポート番号や文字コードを取り違える事故がしょっちゅう起きる。実行する前に機械的に確認する仕組みを作ってほしい」という要望から、コマンドを実行する直前に割り込んで、値の出典を検査するガードを作った。これは以前書いた「助言から強制へ」という発想の延長にある。
AIコーディングアシスタントに「やらせない」仕組みを作る — 助言から強制へ、そして関門に空いていた横穴
作り込みの途中で、このガード自身が自分の検査対象に自分を巻き込むという、地味だが面白い欠陥を2回踏んだ。
値の出典を検査するガード
│
├─▶ 実行しようとしているコマンド本文を検査
│ └─ 「ここまでの複数行をまとめてデータとして渡す」構文(heredoc)の
│ 中身まで検査対象にしてしまう
│ └─ その中に書いたコミットメッセージの説明文を
│ 「実行されるコード」と誤認して止める ①
│
└─▶ 「出典不明な値」をリポジトリ全体からgrepで検出
└─ 検査対象に、検証用のテストコード自身も含めてしまう
└─ テストコードに書いた「わざと出典不明にした検証用の値」に
自分のgrepがヒットし、そのテストを常に不合格として扱う ②
①は、複数行のデータをまとめて渡す構文の中身を、実行されるコードだと誤認していた。渡しているのは「実行される命令」ではなく「シェルに渡すただのデータ」なので、この構文の中身は検査対象から除外した。②は、ガードの正しさを確かめるためのテストコードの中に、わざと「出典不明」な値を書いていたところ、ガード自身のgrepがそのテストコードにもヒットしてしまい、テスト自体を無効化していた。テストが置かれているディレクトリを検査対象から除外して直した。
どちらも根は同じで、「検査する側」と「検査される側」の境界を、パスやディレクトリの区別だけで済ませていて、中身の性質（データなのかコードなのか、本番なのかテストなのか）まで見ていなかったことだった。敵対的な入力を想定したテストを24項目書き直し、実際に配置した環境でもすべて合格することを確認してから使い始めた（前節の#4と同じ24という数だが、こちらはガード専用の別のテスト一式で、中身は関係がない）。
まだ測っていない16秒の中身
四つの無駄を潰しても、初回応答は10秒台に留まっている。0秒にはならない。関所の中の検索処理だけを取り出して測ると、実際には数秒で終わる呼び出しがほとんどだった。
検索処理単体の実測（5回・別プロセス）
import 2.02 s
1回目 72.38 s ← 判定器のモデル読み込みを含む初回
2回目 13.48 s
3回目 4.83 s
4回目 5.04 s
5回目 3.99 s
中央値 5.04 s 最小 3.99 s 最大 72.38 s 平均 19.94 s
修正前の履歴（256件の実測）では、この検索処理単体の中央値は65.93秒、p90は117.14秒だった。ここまで見ると「検索処理を直せば直るほど速くなる」ように思えるが、実際に測った初回応答（10.48秒）と、検索処理単体（中央値5.04秒）を突き合わせると、検索処理を今よりさらに速くしても、初回応答全体への効き目は限定的という見立てになる。関所を通ったあとにも、まだ測っていない区間が残っている。
次に切り分けるべきは、応答本文が生成され始めるまでの、モデル側の処理時間そのものだ。四つの無駄を潰したことで、ようやく「関所の外側」を疑える状態になった。