3つの計測を行き来しよう
ここまでで、3本の懐中電灯が揃いました。
- slow query logは、SQLの時間・回数・調べた行数を見せる
- access logは、URLごとの回数・待ち時間・転送量を見せる
- pprofは、Goの関数ごとのCPU時間を見せる
ここからは「次は必ずこのツール」と決まっていません。アクセスログで回数の多いURLを見つけ、pprofで中へ入り、SQLが原因ならスロークエリログへ戻る。この往復をAgentに任せつつ、人間は判断の筋道を確認します。
自走を頼むプロンプト
ここからはslow query log、access log、pprofを行き来し、計測→仮説→改善→再計測を自走してください。
- 解説記事や既存の解答は見ず、公式マニュアル、実装、実測だけを使う
- 毎回、一番大きい数字だけでなく、回数・合計時間・遅い側の値も比べる
- ベンチは1分かかるので、同じ原因の変更はまとめてよい
- 大きな構造変更も、仕様と計測から説明できるなら試してよい
- 変更前に仮説を一文で残し、変更後は必ずベンチを実行する
- pass、deduction、timeout、HTTP 5xx、serviceの状態も確認する
- スコアが大幅に落ちた変更、意味が変わった変更、説明できない変更は戻す
- 失敗した実験も、観測・結果・戻した理由を短く履歴へ残す
- 最後は再起動し、serviceの自動復帰と再起動後のベンチを確認する
約1時間を目安に、残り時間とベンチ1回の時間を見ながら進めてください。
各loopの終わりに、次に見る数字を人間へ短く説明してください。ここからはslow query log、access log、pprofを行き来し、計測→仮説→改善→再計測を自走してください。
- 解説記事や既存の解答は見ず、公式マニュアル、実装、実測だけを使う
- 毎回、一番大きい数字だけでなく、回数・合計時間・遅い側の値も比べる
- ベンチは1分かかるので、同じ原因の変更はまとめてよい
- 大きな構造変更も、仕様と計測から説明できるなら試してよい
- 変更前に仮説を一文で残し、変更後は必ずベンチを実行する
- pass、deduction、timeout、HTTP 5xx、serviceの状態も確認する
- スコアが大幅に落ちた変更、意味が変わった変更、説明できない変更は戻す
- 失敗した実験も、観測・結果・戻した理由を短く履歴へ残す
- 最後は再起動し、serviceの自動復帰と再起動後のベンチを確認する
約1時間を目安に、残り時間とベンチ1回の時間を見ながら進めてください。
各loopの終わりに、次に見る数字を人間へ短く説明してください。「速そう」でも戻した2つの実験
自走中、pprofとスローログから次の候補が見えました。
1つ目はsessionの確認です。署名済みcookieの復号と「このuserはいるか」というSQLが何千回も呼ばれていました。cookieとuser IDをmemoryへ覚える実験をしましたが、スコアは25,425から18,940へ低下。passはしても、1分ベンチの揺れで片づけにくい差なので戻しました。
2つ目はISU一覧のN+1です。一覧を取ったあと、ISU1台ごとに最新状態を取っていました。最新状態cacheを広げ、1回のJOINにする実験では、最初にSQLの予約語を引用し忘れて状態更新が500になりました。修正後は21,254でpassしましたが、直前の最高点を下回ったため、この構造変更も採用しませんでした。
失敗は「Agentがだめだった」で終わりません。
- ローカルで分かるコンパイルエラーは、デプロイ前のbuildで止める
- SQLは実際のDBで実行しないと分からない失敗がある
passだけでなく、endpoint別のstatusと意味を確認する- 改善を小さなcommitに分けておくと、安全な地点へ戻りやすい
この4つが、次のloopを速くします。
最高点より、正しく動く採用版
EC2を再起動したあと、nginx・MariaDB・Goアプリ・pprofが自動で復帰しました。その状態のベンチでは、一時25,841が出ました。
しかしアクセスログを確認すると、状態POSTの約10%が500でした。履歴の保存は成功していたためスコアは出ますが、最新状態cacheの更新SQLが予約語の引用漏れで失敗していました。既知の500を残した最高点は採用できません。
SQLを直した最終ベンチは次の結果です。
| 項目 | 最終結果 |
|---|---|
| スコア | 20,306 |
| pass | yes |
| deduction | 0 |
| timeout | 2 |
| HTTP 5xx | 0件 |
| 最新状態cacheの時刻不一致 | 0件 |
| 負荷中に増えた利用者 | 33人 |
最新状態が正しく更新されたことでサービス評価が上がり、ベンチマーカーが利用者を増やしたため、壊れていた最高点とは負荷条件も変わりました。ここでは20,306を採用します。
今回の1時間を振り返る
初期1,284から、最終採用版は20,306になりました。約15.8倍です。途中の最大値を競うだけなら別の数字を選べますが、再起動でき、500がなく、cacheと元データが一致するところまでが今回のゴールです。
| 大きな節目 | スコア | 次を決めた観測 |
|---|---|---|
| 初期状態 | 1,284 | timeout 386。原因はまだ不明 |
| slow query 1回目 | 7,125 | trend 68秒、一覧から約50万行 |
| slow query 2回目 | 18,572 | SQLの大きな山が消えた |
| nginxで静的配信 | 19,628 | icon 117MB |
| icon cache | 20,390 | pprofでログとJSON整形が上位 |
| pprof改善 | 24,516 | trendが2.42秒 |
| 正しさ確認済み最終版 | 20,306 | 5xx 0、cache不一致0 |
AI Agentは、大量のコードを一気に書けます。だからこそ、人間の役目は小さくなりません。どの数字を見たか、変更が仕様を守っているか、悪化したら戻せるか。そこを一緒に考えると、Agentはとても強いチームメンバーになります。
そして何より、スコアが跳ねる瞬間はやっぱり楽しいです。次は自分たちの環境で、最初の一本の懐中電灯をつけてみましょう。