チーム白金動物園として ISUCON 9 本選で優勝しました

白金動物園（mirakui、sorah、rosylilly）として、ISUCON 9 優勝を果たしました。

一週間経ってようやく気持ちが落ち着いてきたので参加記を書きます。といってもチューニングの流れはすでに rosylilly が詳細を書いてくれているのでそちらを参照。

rosylilly.hatenablog.com

今回も僕は主にプロファイリングを担当していました。予選では個人ライセンスがたまたま余っていた New Relic をメインで使ったのですが、データが反映されるまでの遅延が気になり、本選ではほとんど使いませんでした。 今回は主に以下のようなツールを使いました。

予選から本選の間に、遅めの夏休みをとって、復習や対策などをしていました。そのおかげか今回は久々に本選でも無にならず、チームに貢献できたような気がします。

工夫したこと

プロファイリングという観点で、今回は特に以下のことをやりました。

「速いクエリ」を減らす

今回、MySQL のスローログは long_query_time = 0 にして、常に全部のクエリを出させていました。遅いクエリについ目が行ってしまいがちですが、ISUCON のような高トラフィック環境下では、10 ms もかからないようなクエリでも、量があることでアプリケーションの負荷になることがあります。スロークエリというのはインデックス張ったりしてわりと早めに減らせてしまうので、スロークエリだけを見ていると「あーもう DB ネックじゃなくなったね」という誤解をすることがあります（予選のときにこの思考になってしまってた）。今回は速いクエリに注目していたことで、大量に呼ばれているクエリに気づきやすくなりました。

アクセスログにユーザ ID を出す

近年の ISUCON の問題はキャッシュ戦略を取りにくくするために、ログインが必須なサービスであることが通常になっています。リクエストを一つ一つ独立したものとして分析するのではなく、一連のログインセッションとして分析することで、ベンチマーカーのシナリオを察することができます。そのために、Nginx のアクセスログに、ログインユーザの ID を記録するようにしました。具体的には、 Sinatra の after ブロックの中でユーザ ID をレスポンスヘッダに書かせ、それを Nginx のログに含めさせました。

after do
  response.headers['X-Isu-UserId'] = session['user_id'].to_s if session['user_id']
end

POST パラメータのログを出す

POST リクエストについては、Nginx のアクセスログにパラメータが記録されないので、アプリケーション側で別ファイルに JSON で書き出すようにしました。このログを前述の trdsql で分析することで、「 POST /api/train/reserve には seats パラメータが空のリクエストはどのくらい来てる？」といった疑問にすぐ答えることができました。

trdsql は今回から初めて使い始めたのですが、LTSV や JSON のログファイルを分析する時にとにかく便利で、もっと早く使っておけばよかったと後悔しています。

アクセスログやクエリログにリクエスト ID を出す

アプリケーション側でリクエストごとにユニーク ID を生成し、Nginx のアクセスログや、MySQL のクエリログなどに出すようにしました。SQL にはリクエスト ID をコメントとして含めました。これによって、どのリクエストでどのようなクエリが発行されているかが簡単に分析できるようになりました。また、クエリログに似たような SQL が大量に吐かれているとき、リクエスト ID を見れば、1リクエストから大量に N+1 で出ているのか、複数のリクエストから同じクエリが叩かれているのかがすぐに分かります。

例えば以下のようなクエリがログに流れてるイメージです。

SELECT * FROM `seat_reservations` WHERE `reservation_id` = 1 /* reqid:b65e78e6-d151-4063-8328-953fbe4210a6 */

stackprof の flamegraph html を自動生成して競技用サーバの Nginx で公開する(sorah)

これをやってくれたのは僕ではなく sorah なんだけどめちゃくちゃ便利でした。ベンチのたびに特定の URL に見に行けば最新の flamegraph が見られます。なお最近の stackprof は mame さんが --d3-flamegraph というオプションを追加してくれていて、とても見やすくなりました。 あまりに便利だったので最後の最後まで使っていて、stackprof を有効にしたまま最終スコアとして提出していたことに後で気づきました……。

最後に

スクリーンに「白金動物園」の文字が表示された瞬間、思わず絶叫し、その後も懇親会が終わるまで手がずっと震えていました。前に立って話したのは sorah だけで、僕は声を出すと泣きそうだったので何も言えませんでした。 たくさんのおめでとうを頂き、僕たちの優勝を喜んでくれる人が多くいることを知り、さらに胸が熱くなりました。 一週間経ってもこの喜びをうまく言葉にできないけど、間違いないのは、僕たちはあの時間を誰よりも楽しむことができたと思います。 以上、白金動物園でした。