【ISUCON14】近傍マッチングの次に詰まったのは、DBではなく接続待ちだった

近傍マッチングによってスコアは1,000台から5,000台まで伸びた。しかし、ベンチ結果には「椅子の実移動時間への不満99.3%」が残った。

近い椅子を割り当てているのに、なぜ移動時間の評価がほぼ全滅するのか。ライド完了数、椅子の稼働状況、APIとMySQLの時間を分けて調べた。

結論から言うと、SQL自体ではなく、SQLを実行する前のDB接続待ちがボトルネックだった。接続プールの上限を10から50へ増やすと、スコアは16.1%、完了ライド数は24.7%改善した。その一方で、次に試した通知トランザクションの削除は局所的なレイテンシを改善したものの、スコアが落ちたため採用しなかった。

近傍マッチング後の状態

近傍化後の代表値は次のとおりだった。

アクティブな椅子は全台使われていた。椅子が余っているのではなく、処理中の椅子がベンチ終了まで戻ってこないことが問題だった。

ステータス間の実時間も確認した。

MySQLは速いのにAPIが遅い

MySQLのクエリ実行時間は平均735µsだった。一方、椅子の移動に関わるAPIは数百ms掛かっていた。

SQLそのものでは説明できない差がある。Node.js実装を見ると、mysql2の接続プールに上限を指定していなかった。既定の接続数は10である。

通知ポーリングと座標送信が同時に走ると、各リクエストはSQLを実行する前に接続の空きを待つ。この待ち時間はスロークエリログには現れないが、NginxのアクセスログにはAPI時間として現れる。

接続プールを10から50へ増やす

まず原因を分離するため、変更を1行に限定した。

const pool = createPool({
  // ...
  connectionLimit: 50,
});

比較ベンチの結果は次のようになった。

接続数を増やすだけで、完了数と主要APIの待ち時間が改善した。近傍SQLではなく、DB接続待ちが椅子の回転を止めていたことが分かる。

マッチ待ち不満44%という逆説

スコアが伸びた一方、マッチ待ち不満は44.0%まで悪化した。

ただし、DB上のライド作成からENROUTEまでの実時間は悪化していない。

ISUCON14のベンチは実時間ではなく仮想世界のtickで満足度を判定する。APIが速くなると世界全体のtickも速く進む。しかしMatcherは0.5秒間隔のままだ。そのため、実時間では短縮していても、マッチまでに経過するtick数は増えることがある。

これは「不満率だけを見ると遅くなったように見えるが、実際の処理能力は上がっている」という計測上の注意点である。

次にCOMMITが支配的になった

接続プール拡大後、MySQL実行時間に占めるCOMMITの割合は54.1%から60.4%へ上がった。

chairGetNotification と appGetNotification は短い間隔で繰り返し呼ばれる。そのたびに明示的なトランザクションを開始し、通知する新しい状態がなくてもCOMMITしていた。

そこで次の比較では、まず chairGetNotification だけから明示的な beginTransaction、commit、rollback を外す。通知済み時刻の更新はautocommitに任せ、変更範囲を一方のAPIだけに限定する。

比較ベンチ結果

スコアだけを見ると悪化している。しかし、この回は作成されたライド自体が125件から113件へ9.6%少なかった。完了数は91件から87件への4.4%減に留まり、完了率は72.8%から77.0%へ上昇した。

さらに、狙っていた chair notification のp95は28.4%短縮し、COMMIT回数は44.0%、COMMIT総時間は27.8%減った。座標送信やステータス更新も速くなっている。局所的な指標だけなら成功に見える。

しかし今回は変更を採用せず、トランザクションを元に戻した。ベンチには揺れがあるとはいえ、スコアは10.3%、完了数は4.4%落ちている。COMMITを減らせたという理由だけで、本来の評価指標の悪化を無視することはできない。

この結果から分かったのは、「ボトルネックらしい処理を減らすこと」と「ベンチ全体の処理能力を上げること」は同じではない、ということだった。通知処理では、トランザクションが複数の読み書きに与えている整合性やタイミングも含めて、改めて検証する必要がある。

採用した変更と見送った変更

この時点で採用したのは、再現性のある改善が確認できたDB接続プールの拡大だけである。connectionLimit: 50 は維持した。

一方、chairGetNotification のトランザクション削除は巻き戻した。API単体のレイテンシやCOMMIT量は改善したが、スコアと完了数で優位性を確認できなかったためだ。

次の仮説はMatcherの実行間隔である。デプロイ済み構成の0.5秒間隔は、API高速化後のtick進行に対して相対的に長い可能性がある。0.1秒とのA/B比較で、マッチ待ち不満、割当数、完了数、/api/internal/matching の負荷を同時に見る。ただし、ローカルではベンチ実行環境が揃わなかったため、この記事の時点では未検証として扱う。

なお、検証の反復を速くするため、Node.js用Dockerfileは package.json と package-lock.json を先にコピーして npm ci を実行し、その後にソースをコピーする構成へ変更した。node_modules と dist は .dockerignore で除外した。これはランタイム性能の改善ではないが、コード変更のたびに依存関係を入れ直さずに済む。

まとめ

今回の調査で重要だったのは、MySQLのクエリ時間とAPIの応答時間を分けたことだ。

• 近傍マッチング後は、全椅子が未完了ライドを抱えて終了していた
• SQLは平均1ms未満でも、APIは接続待ちによって数百ms掛かっていた
• 接続プールを10から50へ増やすと、スコアは16.1%、完了数は24.7%伸びた
• 高頻度ポーリングのCOMMITが次のボトルネックとして顕在化した
• 通知トランザクションを削除すると局所指標は改善したが、スコアと完了数が落ちたため採用しなかった
• 最適化は、狙った内部指標ではなく最終的なベンチ結果まで見て採否を決める必要がある

速いSQLを書くだけではアプリケーションは速くならない。接続を待つ時間、トランザクションを確定する時間、そしてベンチが何を時間として評価しているかまで追う必要がある。さらに、局所的に速くなった変更でも、全体のスコアが改善しなければ一度戻す。その判断まで含めて、ISUCONの最適化だと感じた。