private-isu で50万点を超えるまで with isutools

ISUCON の練習問題 private-isu を1日かけてチューニングし、Go 実装のスコアを 0 → 541,650(fail は常に 0) にした。全ての改善は自作の計測ツール isutools の数字を根拠に行った。この記事では「どの計測が、どの修正を導き、スコアがどう動いたか」を時系列で残す。

改善ステップとスコアの対応は次のとおり。

環境#

• WSL2 + Docker Compose(private-isu 標準構成: nginx / Go app / MySQL / memcached)
• 競技エミュレーションとして app と MySQL は各 1 CPU に制限(compose の cpus: "1")。ホストは 24 コアだが使わない
• ベンチマーカーは同一ホストの Docker で実行

計測基盤: isutools#

チューニングを始める前に、計測を1箇所に集める Go モジュール isutools を作った(導入手順と全機能は単体の紹介記事にまとめてある)。アプリへの組み込みは実質1行:

db, _ = sqlx.Open(isutools.SQLDriverName("mysql"), dsn)

これで localhost:19191 に管理サーバが立ち、POST /reset → ベンチ → POST /save?score=N を繰り返すだけで、ベンチのたびに以下がダッシュボードへ残る:

• SQL(正規化クエリ別 total/count/p95)/ HTTP(パス別)/ nginx アクセスログ(alp 相当)
• プロセス別 CPU と マシン全体の CPU 使用率(busy/idle 内訳)
• DB スキーマ(ベンチ開始時点のインデックス一覧) / 「未設定の定石」を検出する advisor
• ベンチごとのスナップショット履歴と、実行間の diff ビュー
• CPU プロファイル(pprof)の自動採取・セッション単位の User Flow(ページ遷移)

ホームは実行履歴の一覧で、この1日の全ランが git rev・スコア付きで並ぶ。行をクリックすると当時の全計測が開く。

以降の各ステップは、すべてこのダッシュボードのどれかのセクションが指した先を直しただけだ。

時系列の改善ログ#

初期状態: score 0(fail 55)#

Go 実装はタイムアウトの嵐で score 0。SQL セクションの1位は SELECT * FROM comments WHERE post_id = ? ORDER BY created_at DESC LIMIT 3 が 合計450秒 / 1,118回。DB スキーマ欄を見ると comments にインデックスがない。プロセス欄では mysqld が CPU 57%。

① インデックス + N+1 一括化 → 19,290#

comments(post_id, created_at) と posts(created_at) を追加。makePosts の3重 N+1(COUNT・最新3コメント・ユーザー)を GROUP BY / window 関数 / IN 句の3クエリに一括化し、タイムラインは JOIN + LIMIT 20 に。タイムアウトが全滅して初の正のスコア。

② 画像の静的配信 → 34,224#

HTTP 欄の帯域上位が /image/*(合計 180 秒近く)。DB に入っている画像を一括でファイルに書き出し、nginx の try_files + expires 1d で直接配信。アプリには「DB から読んだら次回用にファイルへも書く」write-through を入れた。

③ sha512 内製化ほか → 45,812#

HTTP 欄で POST /login が 63 秒。コードを見るとパスワードハッシュ計算が リクエスト毎に openssl コマンドを exec していた。crypto/sha512 のプロセス内計算(出力は完全互換)に置換。あわせて /posts/:id のクエリから使わない imgdata カラムを外した。

④ write-through の配置バグ修正 → 111,756(2.4倍)#

「画像を静的化したのにアプリ経由の画像配信が減らない」と計測が言う。調べると、②で入れた os.WriteFile が配信成功ブランチの return の後に置かれていて一度も実行されていなかった。成功パス内に移動しただけでスコアが 2.4 倍。計測がなければ「静的化は済んだ」と思い込んだままだった。

⑤ 接続チューニング → 299,668#

CPU 全体使用率の新機能が「busy 11.6% / idle 88.2%」を表示 — ハードは全然飽和していない。db.SetMaxOpenConns と GOMAXPROCS=2(1CPU クォータに対する Go スケジューラ空転の抑制)を入れるとスループットが急増した反動で、nginx→app の接続枯渇による 502 の嵐(score 0)に突入。upstream keepalive + worker_connections 4096 で解決して一気に 30 万点へ。

⑥ advisor の指摘を適用 → 348,416#

isutools に「ISUCON の定石なのに未設定のもの」を検出する advisor を実装したところ、初回実行で interpolateParams なし(プリペアドステートメントの2往復)/ nginx gzip なし / innodb_buffer_pool_size 128MB(データ+索引 1,189MB の9分の1) を即指摘。3件適用で +16%。

適用後は buffer_pool の warn 1件だけが残る(コンテナのメモリ 1GB 制限による実質上限)。「直したら ok に変わる」ので、チェックリストとしてそのまま機能する。

⑦ ユーザーキャッシュ + MySQL 書き込み設定 → 363,733#

sync.Map のユーザーキャッシュ(/initialize と ban で全クリア)を導入。isutools.Count で計装したところヒット率 99.85%(hit 710,745 / miss 1,064)がダッシュボードに出る。MySQL は innodb_flush_log_at_trx_commit=2 + binlog 無効。

⑧ コメントキャッシュ → 412,057#

post_id → 全コメント(新しい順) の単一キャッシュにして、件数 = len()、最新3件 = 先頭3件で導出。makePosts の SQL 2本(合計 94 秒/ベンチ)が消滅。ヒット率 97.9%。

⑨ 事故: インデックス追加で 140,914 に急落#

ユーザーページ用に posts(user_id, created_at) を追加した直後、スコアが 1/3 に。diff とSQL 欄が即座に犯人を特定: タイムラインの JOIN クエリが 2ms → 519ms(260倍)。新インデックスにオプティマイザが引き寄せられて実行計画が壊れていた。

修正後の diff ビューがこれだ。JOIN クエリの -352秒 が緑で消え、代わりに NOT IN 版のクエリが数秒で済んでいるのが一目で分かる:

⑩ フラグメント事前バイト列化 + 退行修正 → 541,650#

仕上げに3点セット:

• 論理削除ユーザー ID をメモリに保持し、タイムラインを JOIN から user_id NOT IN (...) + idx_created_at に変更(⑨の根治)
• タイムライン1ページ目の行キャッシュ(投稿/ban/initialize で無効化)
• 投稿 HTML フラグメントの事前バイト列化: post.html 相当を手動レンダリングして CSRF トークン位置で分割キャッシュ。リクエスト時は3分割の結合だけ

手動レンダリングは、投入前にテンプレート出力とのバイト単位一致を検証した。ここで html/template が UTF-7 対策で + を + にエスケープする仕様を踏む(+09:00 のタイムゾーンやコメント中の顔文字が差分として検出された)。ベンチマーカーは HTML の構造を検査するので、この事前検証がなければ fail の山だった。

学び#

1. 推測より計測。 10 回のスコア更新のうち、事前の予想と違う場所がボトルネックだったことが何度もあった(write-through バグ、GOMAXPROCS、オプティマイザ退行)。毎ベンチの自動スナップショットと diff があると「改善したのか、ボトルネックが移動しただけか」が一目で分かる
2. 速くすると別の壁に当たる。 ⑤でアプリを速くした瞬間、nginx→app の接続が枯渇して score 0 になった。502 の嵐はチューニングが効いている兆候でもある
3. インデックスは無料ではない。 追加した瞬間に別クエリの実行計画が壊れることがある(260倍)。追加後に必ずベンチを回す
4. benchmarker は正しさも見ている。 セッションを CookieStore に変えたときは CSRF 検査(422 期待)が通らず即 fail。速度と引き換えに挙動を変えると検出される設計になっている
5. 計測のオーバーヘッドは作り込みで消せる。 isutools を有効にしたままの ABBA 計測(off→on→on→off)で差は -0.58%、つまり誤差内だった

isutools を使ってみる#

この記事の計測はすべて isutools(MIT ライセンス)によるもの。組み込みは sqlx.Open の1行書き換えだけで、SQL / HTTP / nginx ログ / プロセス / DB スキーマ / pprof / advisor / diff / User Flow までまとめて手に入る。計測オーバーヘッドは ABBA 計測(off→on→on→off)で -0.58% = 誤差内を確認済み。

db, _ = sqlx.Open(isutools.SQLDriverName("mysql"), dsn)

ISUCON の練習・本番はもちろん、Go 製 Web アプリの性能調査全般に使えるはず。バグ報告・機能要望は GitHub Issues へ。Star をもらえると開発の励みになります。

残りの伸びしろ#

Gurrium さんの 100 万点の記録と比べると、残りは「セッション管理の自前化」「ページシェル(layout)のテンプレート脱出」「pprof 起点のマイクロ最適化」あたり。現在の 541,650 は彼の軌跡の 25 日目(814,586)手前に相当する。続きはまた別の記事で。

リンク#

• 計測ツール(OSS): github.com/ekusiadadus/isutools
• チューニング対象: github.com/ekusiadadus/private-isu(catatsuy/private-isu のフォーク)
• 参考: 達人が教えるWebパフォーマンスチューニング、Gurrium さんの private-isu 連載