@sora_h @rosylilly と3人でチーム「白金動物園」として ISUCON 5 に参加し、本選で2位を獲得しました。
主な分担としては sorah と rosylilly の2人が実装をして、僕はインフラまわりの整備と、ログ分析や指示出し、あと二人が喧嘩したら仲裁をするという分担でした。今年は二人が喧嘩しなかったので仲裁役は必要なくて良かったです。
（追記 2015/11/02 14:14）2人の記事が揃ったので以下にリンクしておきます。HTTP/2 まわりのチャレンジなどは彼らの記事に詳しいです。
- sorah: ISUCON5 で準優勝してきた #isucon - diary.sorah
- rosylilly: ISUCON5 で準優勝しました - 鳩舎
やったこと
今回の問題はマイクロサービスがテーマになっていて、運営側が用意した API サーバへリクエストを発行する部分がありました。そのテーマが発表されたとき、直感的にこれは Ruby には不利な課題かもしれないなと感じましたが、慣れた道具ということで Ruby を選択しました。
11:00 試合開始
Ruby 参考実装の初期状態では、スコアは 1,000 点くらいでした。
まず最初にやったのは、負荷走行を実行して Nginx のアクセスログを分析しました。ログの分析には自前のスクリプトを持ち込みました。 ISUCON はとにかく時間との闘いなので、やみくもにチューニングするのではなく、初手でボトルネックを特定しにいきました。 Ruby 参考実装の初期状態を URL ごとに分析した結果が以下です。
Most Time Consumed
| request | total_time | ratio |
|---|---|---|
| 200 GET /data | 3,056,797 | 95.78 % |
| 200 GET /login | 60,565 | 1.90 % |
| 200 GET /user.js | 13,771 | 0.43 % |
| 200 GET /css/bootstrap.min.css | 9,822 | 0.31 % |
| 200 GET /js/jquery-1.11.3.js | 6,594 | 0.21 % |
| 200 GET /js/bootstrap.js | 6,587 | 0.21 % |
| 302 POST /modify | 6,302 | 0.20 % |
| 403 GET /modify | 6,264 | 0.20 % |
| 403 GET /data | 5,799 | 0.18 % |
| 200 GET /js/airisu.js | 5,333 | 0.17 % |
| 200 GET /css/signin.css | 3,213 | 0.10 % |
| 200 GET /css/jumbotron-narrow.css | 2,989 | 0.09 % |
| 200 GET / | 2,544 | 0.08 % |
| 302 POST /login | 2,386 | 0.07 % |
| 499 GET /modify | 1,709 | 0.05 % |
| 200 GET /initialize | 735 | 0.02 % |
| 302 POST /signup | 42 | 0.00 % |
| 200 GET /modify | 30 | 0.00 % |
| 200 GET /signup | 17 | 0.00 % |
| 302 GET / | 15 | 0.00 % |
| 304 GET /css/bootstrap.min.css | 9 | 0.00 % |
| 304 GET /js/bootstrap.js | 6 | 0.00 % |
| 304 GET /js/airisu.js | 3 | 0.00 % |
| 304 GET /js/jquery-1.11.3.js | 2 | 0.00 % |
| 304 GET /css/jumbotron-narrow.css | 1 | 0.00 % |
Request Count
| request | count | ratio |
|---|---|---|
| 200 GET /data | 498 | 41.29 % |
| 200 GET /css/bootstrap.min.css | 126 | 10.45 % |
| 200 GET /css/signin.css | 72 | 5.97 % |
| 200 GET /login | 68 | 5.64 % |
| 302 POST /login | 64 | 5.31 % |
| 200 GET / | 59 | 4.89 % |
| 200 GET /user.js | 55 | 4.56 % |
| 200 GET /js/airisu.js | 54 | 4.48 % |
| 200 GET /js/bootstrap.js | 54 | 4.48 % |
| 200 GET /js/jquery-1.11.3.js | 54 | 4.48 % |
| 200 GET /css/jumbotron-narrow.css | 54 | 4.48 % |
| 302 POST /modify | 20 | 1.66 % |
| 403 GET /data | 4 | 0.33 % |
| 200 GET /modify | 4 | 0.33 % |
| 302 POST /signup | 4 | 0.33 % |
| 200 GET /signup | 4 | 0.33 % |
| 302 GET / | 4 | 0.33 % |
| 403 GET /modify | 1 | 0.08 % |
| 499 GET /modify | 1 | 0.08 % |
| 200 GET /initialize | 1 | 0.08 % |
| 304 GET /js/airisu.js | 1 | 0.08 % |
| 304 GET /js/bootstrap.js | 1 | 0.08 % |
| 304 GET /css/jumbotron-narrow.css | 1 | 0.08 % |
| 304 GET /js/jquery-1.11.3.js | 1 | 0.08 % |
| 304 GET /css/bootstrap.min.css | 1 | 0.08 % |
Average Request Time
| request | reqtime | ratio |
|---|---|---|
| 403 GET /modify | 6,264 | 34.06 % |
| 200 GET /data | 6,138 | 33.37 % |
| 499 GET /modify | 1,709 | 9.29 % |
| 403 GET /data | 1,449 | 7.88 % |
| 200 GET /login | 890 | 4.84 % |
| 200 GET /initialize | 735 | 4.00 % |
| 302 POST /modify | 315 | 1.71 % |
| 200 GET /user.js | 250 | 1.36 % |
| 200 GET /js/jquery-1.11.3.js | 122 | 0.66 % |
| 200 GET /js/bootstrap.js | 121 | 0.66 % |
| 200 GET /js/airisu.js | 98 | 0.53 % |
| 200 GET /css/bootstrap.min.css | 77 | 0.42 % |
| 200 GET /css/jumbotron-narrow.css | 55 | 0.30 % |
| 200 GET /css/signin.css | 44 | 0.24 % |
| 200 GET / | 43 | 0.23 % |
| 302 POST /login | 37 | 0.20 % |
| 302 POST /signup | 10 | 0.05 % |
| 304 GET /css/bootstrap.min.css | 9 | 0.05 % |
| 200 GET /modify | 7 | 0.04 % |
| 304 GET /js/bootstrap.js | 6 | 0.03 % |
| 200 GET /signup | 4 | 0.02 % |
| 302 GET / | 3 | 0.02 % |
| 304 GET /js/airisu.js | 3 | 0.02 % |
| 304 GET /js/jquery-1.11.3.js | 2 | 0.01 % |
| 304 GET /css/jumbotron-narrow.css | 1 | 0.01 % |
この結果を踏まえると、/data へのリクエストが圧倒的なボトルネックになっていて、ここを改善するべきという事が分かりました。コードを読むと、いくつかの外部 API エンドポイントへリクエストを発行しているようでした。つまり、ここが今回のテーマになっているマイクロサービスとの通信部分です。
また、静的な JS や CSS へのリクエストも意外に多かったので、このあたりも改善の余地がありそうでした。
12:00
問題に使われている DB は Postgres でした。これを自分たちがチューニングに慣れている MySQL に置き換えるべきかどうかという議論になりました。
しかし、今回は /data の中で発行されている外部への API リクエストをどう効率的に処理するかというところが大きなボトルネックであり、DB の速度があまりパフォーマンスに影響していないということに気づいていたため、MySQL への移行は悪手であると判断し踏みとどまりました。限られた時間の中では、ボトルネックの解消が最優先であり、余計なことに時間を使わないのが大事です。Postgres に入っているテーブルには一つもインデックスが無かったため、適宜インデックスを作成しました。クエリも単純なものしか無かったため、それだけで十分でした。
次に、与えられていた3台のホストを使い切るために、Nginx を使ってラウンドロビンで3台の Unicorn に負荷分散するようにしました。
sorah が外部 API エンドポイントの一つが HTTPS であることに気づき、HTTP/2 での通信を試したところ、ネゴシエーションに成功しました。このあたりから、sorah はAPI リクエストの HTTP/2 化に挑戦しはじめます。
ホストの負荷分散が効いて、スコアは 7,797 点になりました。
13:00
/data では複数の API リクエストが発行されていました。これを sorah が Expeditor を使って多重化しました。Expeditor はクックパッドが開発している、 HTTP リクエストを非同期かつ並列に実行するための Ruby ライブラリです。まさに今回のようなマイクロサービスとの通信のために作られたものです。
https://github.com/cookpad/expeditor
しかし、この並列処理によって負荷走行が fail するようになってしまいました。その原因は、API エンドポイントの一つが「Too Many Requests」エラーを返してくるようになってしまったからです。仕方なく、一旦 Expeditor を無効化しました。
最初の分析で気づいた静的ファイルの負荷については、ベンチマーカが Accept-Encoding: gzip と言ってきていたので、Nginx の gzip_static を使って gzip で配るようにしました。なお、試しに静的ファイルに expires max を付けてみたのですが、ベンチマーカは Conditional GET してきませんでした。
このあたりで sorah が API リクエストの HTTP/2 化を実装しましたが、謎のプロトコルエラーに悩まされ、リバートしました。
14:00
rosylilly が API リクエストの結果を Redis にキャッシュするようにしました。長時間キャッシュすると fail してしまうので、細かい調整の結果、キャッシュ時間は1.2秒になりました。
API が「Too Many Requests」エラーを返す条件を探るために、いろんな叩き方を試していました。どうやら、同じトークンを指定したリクエストが同時に複数コネクションから実行されると、「Too Many Requests」と判定されることに気づきました。トークンが互いに異なるリクエストなら同時に叩いてもエラーになることはありませんでした。
15:00
sorah が Expeditor による API リクエスト多重化を復活させました。上記のエラー条件を考慮して、同じ API エンドポイントに同じトークンを持つリクエストが同時には行かないようにしたところ、fail しなくなりました。
Ruby による HTTP/2 は件のプロトコルエラーで一度諦めましたが、Go の方が良い HTTP/2 実装があるだろうと判断し、API リクエストのための HTTP/2 フォワードプロキシを rosylilly に Go で書いてもらうことにしました。
16:00
Unicorn のワーカ数などを調整していると、rosylilly が1時間ほどでプロキシを書き終わったので、投入しました。
しかし、やはりここでも Ruby 実装と同様に HTTP/2 のプロトコルエラーが出てしまうため、API サーバの HTTP/2 実装がおかしいのだろうと判断し、HTTP/2 自体をこの時点で諦めました。
HTTP/2 は諦めたものの Too Many Requests 対策のために Go によるプロキシサーバを残し、トークンごとのコネクション排他処理をプロキシ側で行うようにしました。
このあたりでスコアは 69,273 点になっていました。
17:00〜終了
最後の1時間です。
大きな変更を入れるのをやめ、余分なログ出力を消したり、再起動試験をしたりしていました。再起動試験は必ずやりましょう。今年の学生枠のチーム達はどこも再起動に耐えられずに全滅してしまいました。
最後の最後で RACK_ENV が development であることに気づき、production に変更したところ、スコアが2万点くらい跳ね上がりました。懇親会で聞いたところによると、これに気づかずに development のまま提出してしまったチームが結構あったようです。
なお、以下はほぼ最終スコア時点でのログ分析結果です。初期状態で平均 6 秒ほどかかっていた /data が、最終的には平均 61 ms になり、498 リクエストしか捌けなかったのが 34,838 リクエスト捌けるようになりました。
Most Time Consumed
| request | total_time | ratio |
|---|---|---|
| 200 GET /data | 2,158,827 | 79.79 % |
| 200 GET / | 143,896 | 5.32 % |
| 302 POST /login | 131,934 | 4.88 % |
| 200 GET /user.js | 131,372 | 4.86 % |
| 200 GET /login | 129,391 | 4.78 % |
| 302 POST /modify | 5,535 | 0.20 % |
| 200 GET /js/jquery-1.11.3.js | 1,957 | 0.07 % |
| 200 GET /initialize | 1,244 | 0.05 % |
| 200 GET /css/bootstrap.min.css | 290 | 0.01 % |
| 200 GET /modify | 288 | 0.01 % |
| 302 POST /signup | 260 | 0.01 % |
| 200 GET /js/airisu.js | 158 | 0.01 % |
| 200 GET /js/bootstrap.js | 121 | 0.00 % |
| 302 GET / | 99 | 0.00 % |
| 200 GET /signup | 57 | 0.00 % |
| 200 GET /css/signin.css | 56 | 0.00 % |
| 200 GET /css/jumbotron-narrow.css | 39 | 0.00 % |
Request Count
| request | count | ratio |
|---|---|---|
| 200 GET /data | 34,838 | 48.04 % |
| 200 GET /css/bootstrap.min.css | 6,829 | 9.42 % |
| 200 GET /css/signin.css | 3,423 | 4.72 % |
| 200 GET /login | 3,419 | 4.71 % |
| 302 POST /login | 3,415 | 4.71 % |
| 200 GET / | 3,410 | 4.70 % |
| 200 GET /user.js | 3,406 | 4.70 % |
| 200 GET /js/airisu.js | 3,406 | 4.70 % |
| 200 GET /js/bootstrap.js | 3,406 | 4.70 % |
| 200 GET /js/jquery-1.11.3.js | 3,406 | 4.70 % |
| 200 GET /css/jumbotron-narrow.css | 3,406 | 4.70 % |
| 302 POST /modify | 144 | 0.20 % |
| 200 GET /modify | 4 | 0.01 % |
| 302 POST /signup | 4 | 0.01 % |
| 200 GET /signup | 4 | 0.01 % |
| 302 GET / | 4 | 0.01 % |
| 200 GET /initialize | 1 | 0.00 % |
Average Request Time
| request | reqtime | ratio |
|---|---|---|
| 200 GET /initialize | 1,244 | 74.36 % |
| 200 GET /modify | 72 | 4.30 % |
| 302 POST /signup | 65 | 3.89 % |
| 200 GET /data | 61 | 3.65 % |
| 200 GET / | 42 | 2.51 % |
| 302 POST /modify | 38 | 2.27 % |
| 200 GET /user.js | 38 | 2.27 % |
| 302 POST /login | 38 | 2.27 % |
| 200 GET /login | 37 | 2.21 % |
| 302 GET / | 24 | 1.43 % |
| 200 GET /signup | 14 | 0.84 % |
| 200 GET /js/airisu.js | 0 | 0.00 % |
| 200 GET /js/bootstrap.js | 0 | 0.00 % |
| 200 GET /js/jquery-1.11.3.js | 0 | 0.00 % |
| 200 GET /css/jumbotron-narrow.css | 0 | 0.00 % |
| 200 GET /css/signin.css | 0 | 0.00 % |
| 200 GET /css/bootstrap.min.css | 0 | 0.00 % |
2位
白金動物園の最終スコアは 101,858 で、2位となりました。素直にとても嬉しいです。
しかし1位の fujiwara 組とはさらに5万点ほどの開きがあるので、まだまだ力の差があるなあという気持ちです。試合前には「fujiwara さんに勝って ISUCON への恩返しをする」とか「俺たちが優勝することで fujiwara さんを ISUCON から《解放》してあげるんだ」とかエモいことを言ってたけど、それができなかったのが心残りです。
今回の ISUCON 5 は、ISUCON 4 の出題チームである我々が本選に出られないとか本選で勝てないとかいう状況になるとかなりみっともないので、大きなプレッシャーがありました。そのために予選では、確実な予選通過を目指して、大きなアーキテクチャ変更などの飛び道具を封印し、基本のチューニングを地味に重ねて地味なスコアで通過しました。
同じメンバーで2年前に参加した ISUCON 3 は fail に終わったことを思うと、成長を感じます。やはり ISUCON 4 で出題を経験したことが、技術力という面でもチームビルディングという面でも今回の結果に大きく寄与しました。
sorah と rosylilly の2人は社内でもトップクラスに実装力の高い2人で、一緒に作業しているとその速さにいつも驚かされます。たとえば rosylilly にはちょっとゼロから Go で HTTP/2 のプロキシ書いてよみたいな無茶ぶりをすることができるし、（HTTP/2自体は諦めたものの）プロキシを実際に1時間で仕上げてきたうえにバグもありませんでした。マジですごい。でも彼ならそのくらいできると知っていたし、3人がお互いの技量と役割を信頼して任せることができる、良いチームになりました。
最後に
運営チームは本当にお疲れ様でした。素晴らしい問題と安定したベンチマーカのおかげで快適に楽しむことができました。
あと本選当日、 rosylilly は寝坊してタクシーで都外から高速飛ばしてヒカリエまで来たけど、賞金でタクシー代がペイできて良かったです。
