最終スコアはいくつですか？

公式ベンチの最終チェックを通過した採用版は445,684点です。比較可能な計測付きbaseline 12,136点の36.72倍でした。

pprofがpartialならCPU解析に失敗していますか？

必ずしも失敗ではありません。今回のCPU profileはcapture区間が完全で、binary一致を検証し、CPU flame graphもreadyでした。partialは外部依存のsource pathをredactしたことや、CPU以外のflame viewがunsupportedであることを含みます。

一番効いた変更はPGOですか？

単一変更の因果効果とは断定していません。index、N+1削減、memory cache、ETag、JSON compact化、Unix socket、MySQL設定などを含む採用構成の結果です。PGOも実workloadのCPU profileを使った採用項目の一つです。

ISUCON13を12,136点から445,684点まで改善した記録 — isutools・pprof・PGOで次の一手を決める

ISUCON13の公式問題環境をWSL2へ構築し、Go参考実装を 12,136点から445,684点 まで改善しました。最終runはpass=trueで、公式ベンチの最終チェックにも成功しています。

この記事では、自作の計測ツールisutoolsを組み込んで、SQL、HTTP、nginx access log、DB pool、CPU profileを同じベンチ区間で見ながら改善した過程を整理します。

最初に結論を書くと、今回の中心は「遅い処理を1個見つける」ことではありませんでした。数十万回呼ばれる短い処理、DBへの往復、JSON生成、静的に近いレスポンス、DNS攻撃への耐性を同じ公式scoreで評価し、局所的に速くても総合scoreが落ちた変更は戻す、という繰り返しです。

結果

状態	score	pass	位置づけ
WSL構築直後	12,706	true	公式Go実装の起動確認
計測条件を固定したbaseline	12,136	true	最終構成との比較起点
最終採用版	445,684	true	公式最終チェック成功
`make bench`再現run	441,439	true	save・SCP・JSON検証まで完走
pprof UI修正後の確認run	433,468	true	同一PGO profile、機能確認用

445,684点は比較可能baselineの36.72倍です。ただし、ベンチには揺れがあり、複数の変更を含むため、36.72倍を単一施策の因果効果とは扱いません。各runのscore、pass、git revision、CPU profileを一緒に保存し、「どの構成で何が観測されたか」を追跡できるようにしました。

環境

Windows 11 / WSL2
Ubuntu 22.04.3 LTS
ISUCON13 Go参考実装
nginx / MySQL / PowerDNS / isupipe-go
公式ベンチ: ./bench run --dns-port 1053 --enable-ssl
参考にした構築手順: matsuu/wsl-isuconのISUCON13環境

公式checkoutは876bd43a6f6f1048b8d341b2ab62d7afff01efd2へ固定しました。管理画面は外部へbindせず、WSL内のloopbackとSSH port forwardingだけで開きました。

まず計測だけを組み込みました

アプリ側ではSQL driverとEcho middlewareをisutoolsへ接続しました。

db, err := sqlx.Open(isutools.SQLDriverName("mysql"), dsn)
 
echov4.Install(e)
e.Use(echo.WrapMiddleware(isutools.HTTP))

nginxは専用LTSV access logを出し、systemd drop-inから保存先、profile mode、path正規化規則を渡します。管理portは既存の19191との衝突を避け、この環境だけ127.0.0.1:19196にしました。

計測を入れただけの段階では、index、cache、SQL、業務処理には触れていません。この時点の公式benchが通ってから、最適化を始めました。

ベンチ区間と保存を先に固定しました

改善前に、毎回同じ順序で計測できるようにしました。

POST /reset
  -> 公式benchmark
  -> /tmp/result.jsonを型検査
  -> POST /save?score=<score>&pass=<pass>
  -> artifactをWindows側へstage
  -> scpで制御PCへ取得

/resetが返すX-Isutools-Run-Idを、公式結果とisutools snapshotの対応付けに使います。高throughput時はaccess logが大きく、別途/collectすると固定2秒budgetを超えることがありました。そのため、/saveが終了境界を確定し、凍結したgenerationをdrainする経路を使っています。

結果は次のように分けて保存しました。

公式原本: official-benchmark-<time>-<run-id>.json
isutools JSON/HTML: <time>_<seq>_gen<generation>_<rev>_score<score>.json|html
profile: cpu_<capture-id>.pprofとsidecar metadata
制御PC: MakefileのRESULTS_DIR

generationはscoreではなく、reset前後の計測値を混ぜないための内部世代番号です。runの同一性はrun_idで見ます。

1. SQLの回数と実行計画からindexを追加しました

最初に見たのは「1回だけ最も遅いSQL」ではなく、回数 × 1回の時間です。livecomments、reactions、reports、tags、reservation、PowerDNS recordsなどに、実際のfilter・join・orderに合わせてindexを追加しました。

同時に、MySQL接続poolを50へ広げ、interpolateParams=trueでprepared statementの往復を減らしました。index追加後は必ずquery planと公式scoreを再確認しています。

indexは増やせばよいわけではありません。別の練習では新indexをoptimizerが選び、全体が遅くなった経験があります。今回もpossible_keysだけで採用せず、key、rows、Using filesort、総合scoreを一緒に見ました。

2. N+1をまとめ、read pathをmemoryへ寄せました

次に、user/theme/icon、livestream/tag、comment/reaction/report、NG word、統計、予約枠をinitialize時に構築するmemory stateへ寄せました。

特に効果が大きいのは、1件ごとに短いSQLを呼ぶN+1です。単発では速く見えても、数万回・数十万回になるとDB接続とJSON生成を占有します。一括SQLまたはmemory集計へ置き換え、読み取りAPIの不要なtransactionも外しました。

ただし、memoryだけで予約枠を更新する案は不採用にしています。局所処理は軽くなりましたが、DNS attackerの並列度が変わり、総合scoreが417,657へ下がりました。競技では、アプリAPIだけを見て採用すると全体を悪化させることがあります。

3. iconをETagで304にしました

最終snapshotでは、icon GET 281,999件のうち281,642件がHTTP 304でした。icon hashをETagにし、If-None-Matchが一致すればbodyを返さない構成です。

iconの更新もDELETE + INSERTではなく、INSERT ... ON DUPLICATE KEY UPDATEへ変更しました。これは速度だけでなく、同時更新時の空白期間と競合を減らす目的があります。

4. pprofでJSON indentのCPU消費を確認しました

CPU profileでは、JSONを見やすくindentする処理が累計21.36秒を消費していました。競技のAPI responseは人が読むものではないため、Echoをproduction modeにしてcompact JSONへ変更しました。

ここで注意したいのは、CPU使用率が高いからpprof解析できない、ということではない点です。CPU profileは「CPUを使っている場所」を調べるものなので、負荷中の代表的な区間を採ることに意味があります。一方で、profileと解析対象binaryが違うと、function / file / lineの対応は証明できません。

今回の解析では次を確認しました。

benchmark run全体のCPU profileを採取
capture時binaryと解析binaryのSHA-256一致を検証
CPU flame graphはready
flame graphは2,048ノード
source pathの一部はselected root外なので(redacted)

partialという表示だけを見てCPU解析失敗とは判断しません。今回のpartialには、外部依存のsource pathをredactしたことと、block/heap/mutexのflame viewがunsupportedであることが含まれます。CPU flame自体は生成できています。

検証用ビルドでは、レポート上部から次の2つへ直接移動できるようにしました。

行解析結果: verified analysisのfunction / file / line一覧へ移動
CPU pprofフレームグラフ: readyなCPU flameを開いて移動

解析が未publishの場合は、無反応にせずProfilesへフォールバックします。保存済みのimmutable HTMLは書き換えないため、新しいrendererを使う場合はRuns一覧のcurrent UIを開きます。

5. 実workloadのprofileをPGOへ戻しました

GoはCPU pprof profileをPGO入力として利用できます。Go公式のPGOドキュメントでも、代表的なworkloadから採ったprofileをgo build -pgo=<profile>へ渡す流れが説明されています。

今回は公式benchmark区間から採取したprofileを使いました。

go build \
  -pgo=/home/isucon/isutools-data/cpu_<capture-id>.pprof \
  -o isupipe .

profileはbuild inputなので、どのprofileを使ったかをbuild infoと一緒に残しました。古いprofile、別binary、手動で短時間だけ採ったprofileを混ぜると再現性が落ちます。

GOAMD64=v3も試しましたが、441,453点でPGO v1に対する有意な改善を確認できず、採用しませんでした。

6. nginx・MySQL・PowerDNSを全体で調整しました

アプリ以外では次を採用しました。

nginxとGo間をsystemd管理のUnix domain socketへ変更
MySQLのbufferと競技向けdurability設定を調整
PowerDNSの過剰logを停止し、records検索indexを追加
Echo production modeとcompact JSON

MySQLのinnodb_flush_log_at_trx_commit=2などは競技スコア優先です。停電時の直近transaction耐久性が必要な本番環境へ、そのまま転用してはいけません。

採用しなかった変更

局所的にはもっともらしくても、公式scoreで下がったものは戻しました。

変更	結果	判断
PowerDNS cache/thread増加	score低下	DNS攻撃のrampを含めて不採用
予約枠をmemoryだけで更新	417,657	DNS attacker並列数が6から9へ増え不採用
JSON gzip level 1	424,767	約4.3分の1へ圧縮したがCPU負荷が勝ち不採用
`GOAMD64=v3`	441,453	PGO v1との差を確認できず不採用

gzipのように「転送量は減った」という局所指標が改善しても、CPUと公式scoreが悪化することがあります。採否はpass、最終チェック、score、DNS attackerのrampまで含めて決めました。

制御PCから`make bench`する

再現用Makefileはhost固有値を別ファイルへ分けています。

REMOTE_HOST = user@example-host
WSL_DISTRO = isucon13
WINDOWS_USER = your-windows-user
RESULTS_DIR = $(HOME)/isutools-isucon13-results
LOCAL_PORT = 19197

make check
make bench
make tunnel
# http://127.0.0.1:19197/

make benchはreadiness、公式bench、結果型検査、save、Windows stage、SCP、最新JSONの要約まで行います。「serviceがactive」「管理画面が200」だけでは実動確認にせず、公式benchのpass=trueと最終チェックまでをgateにしました。

isutoolsで分かったことと、分からなかったこと

分かったこと:

SQLとHTTPを同じrun境界で比較できる
短い処理でも回数が多いと大きな累計負荷になる
CPU profileからhot functionと呼び出し経路を絞れる
binary一致を検証すればsource lineを修正候補として扱える
変更後のscore、correctness、artifactを同じrun IDへ結び付けられる

分からないこと:

1回のscore差が変更そのものの因果効果か
CPUに出ない待ちの原因がDB、lock、networkのどれか
memory化した状態がすべてのcorrectness条件を保つか
WSL2の結果が本番3台構成でも同じか

そのため、レポート上の「第一修正候補」は原因の断定ではなく、次に確認する順序として扱いました。

まとめ

12,136点から445,684点までの改善で効果的だったのは、個別の秘技より次の運用でした。

公式benchと計測を同じrun IDで保存する
SQLは単発時間だけでなく累計時間と回数を見る
N+1とDB往復を一括SQL・memory stateへ寄せる
ETag、compact JSON、Unix socketで大量の小さなコストを減らす
代表的なCPU profileを解析し、同じprofileをPGOへ戻す
局所指標が改善しても、公式scoreが落ちれば採用しない

isutoolsは最適化を自動で行うツールではありません。SQL、HTTP、CPU、score、correctnessを1つのrunへ揃え、「次に何を試すか」を決めやすくするための道具です。今回一番役に立ったのも、答えを出す機能より、採用しなかった変更を証拠付きで戻せることでした。

結果#

環境#

まず計測だけを組み込みました#

ベンチ区間と保存を先に固定しました#

1. SQLの回数と実行計画からindexを追加しました#

2. N+1をまとめ、read pathをmemoryへ寄せました#

3. iconをETagで304にしました#

4. pprofでJSON indentのCPU消費を確認しました#

5. 実workloadのprofileをPGOへ戻しました#

6. nginx・MySQL・PowerDNSを全体で調整しました#

採用しなかった変更#

制御PCからmake benchする#

isutoolsで分かったことと、分からなかったこと#

まとめ#

参考リンク#

結果

環境