ISUCON公式Blog

WINNER'S PRIZE \1,000,000



商標「ISUCON」利用の
ガイドラインはこちら
スポンサー各社からの応援特設ページ ISUCON10 個人スポンサー

こんにちは、ISUCON10 の本選出題を担当した白金動物園の mirakui です。最近はパン作りにハマっています。この記事では、本選問題であるアプリケーションの「XSUCON」について、問題の概要と想定していた解き方について解説していきたいと思います。

XSUCON とは

近年の ISUCON にはとても多くの方が参加してくださり、スコアランキングを表示したりベンチマーカー実行を指示したりするいわゆる「ポータルサイト」の負荷対策には毎年の出題担当たちが苦労してきました。記念すべき 10 回目の開催である ISUCON10 ではぜひこの ISUCON ポータルサイト自体を問題にしたい、と私たち白金動物園が1年前から温めてきた構想を形にしました。

というわけで ISUCON10 の本選問題は「XSUCON」という、 ISUCON を模した仮想的な競技のポータルサイトでした。XSUCON の世界観を表現するために動画まで作ってしまいました。せっかくなので見てください。



詳しい仕様は下記のマニュアルやソースコードを参照いただければと思います。
ISUCON10 本選当日マニュアル
XSUCON アプリケーションマニュアル
ソースコード (GitHub: isucon/isucon10-final)

簡単に概要を説明すると、
  1. 最初に仮想選手登録・仮想チーム登録リクエストが押し寄せる(初期状態では10チームで締め切り)
  2. 仮想選手たちが仮想負荷走行をエンキューしたり、仮想運営に質問を投げたりする
  3. 仮想運営は、質問が来たら返答を返す
  4. 仮想選手達は仮想負荷走行が終わったかどうかや、質問の回答が来たかどうかを知るために、通知のエンドポイントをひたすらポーリングしまくる
  5. その間も仮想選手や仮想オーディエンスがスコアのダッシュボードを常にポーリングしまくる
といったシナリオでした。

なお本稿および、上記マニュアル等では ISUCON10 本選の用語と XSUCON の用語の混同を避けるため、ISUCON の用語には「実」を、XSUCON の用語には「仮想」をつけて書き分けています。たとえば「実選手」「仮想選手」といった具合です。とってもややこしくておもしろいですね(開発時のコミュニケーションでも常に混乱を招いて大変でした)。

余談ですが、フロントエンドのコードや API 設計等の多くを本選の実ポータルから流用しています。そのため、ブラウザで見たときの見た目はそっくりです(競技中に見間違えないよう背景色は変えておきました)。

01
図1: 仮想ポータルの画面(オーディエンス向けダッシュボード)

アプリケーションの構成

本選問題となるアプリケーションは仮想ポータルと仮想ベンチマークサーバという2つのサーバから成り立っていました。仮想ポータルは HTTPS を、仮想ベンチマークサーバは gRPC を採用していました。

仮想ポータルのフロントエンドは React.js で実装(これはチューニング対象外)したのですが、フロントエンドとサーバとの通信には JSON ではなく Protocol Buffers (以下 protobuf)を利用しました。ですので、仮想ポータルのサーバはあらゆる API レスポンスを protobuf にエンコードして HTTPS で返しています。protobuf を採用したのは gRPC サーバを開発する都合上、全体的に protobuf に揃えたかったというのと、あと本選問題に先行して実ポータルの開発を進めていた sorah の趣味とのことです。protobuf であらゆる API やデータ構造を定義し、仮想ポータル・実ポータル・実ベンチマーカーでバックエンド・フロントエンド通して .proto を共有して開発したところ、開発者間の情報共有やバグの防止においてとても体験がよかったです。

アプリケーションの前段には Envoy があり、これが仮想ポータルと仮想ベンチマークサーバへのリクエストを振り分けていました。Envoy を採用したのは、gRPC と HTTPS の両方を受けて振り分けたいという今回のユースケースと合っていたからというのと、近年 reverse proxy としての事例も増えてきているので最近のネタとしていいだろうという判断でした。

問題設計と出題意図

ここからは、参考実装および実負荷走行シナリオがどのようなチューニングを意図して作られていたかについて解説します。

スコア設計

参考:当日マニュアルのスコア計算式

本選問題のスコアは、「仮想選手・仮想オーディエンス・仮想運営それぞれの視点からの XSUCON の満足度の高さ」がスコアになるように設計しました。これは、ISUCON 3 から参加し続けているチーム白金動物園として、「満足度の高い ISUCON とはどういうものだろう?」ということを議論をして方針を組み立てていきました。その結果として、

XSUCON の仮想選手の視点では、
  • たくさん仮想負荷走行を実行できること
  • 仮想運営への質問がすぐに返ってくること
  • ダッシュボードが正確かつ素早く表示されること
仮想オーディエンスの視点では、
  • ダッシュボードが素早く表示されること
  • 大会が盛り上がっている(=たくさん仮想負荷走行が実行されている)こと
    • 仮想負荷走行が実行されるたびに仮想オーディエンスが 1 人増えるようになっていました
仮想運営の視点では、
  • 多くのチームが参加すること
    • 初期値は10チームですが、100チームまで増やすと仮想選手スコアが最大2倍になるようになっていました(大会規模ボーナス)
という考え方を基本にスコア計算式ができています。仮想選手の満足度はこの中でも特にスコア比重が高いので、問題を解く上ではいかに仮想負荷走行や質問の回答頻度を上げるかが重要になってきます。

3台のサーバのリソース

本選問題では予選と同様に、スポンサーである株式会社サイバーエージェント様のご協力により、競技サーバーとして1実チームあたり3台が提供されました。実選手に対して、特にスペックはアナウンスしませんでしたが、実はこの3台はそれぞれ異なるスペックを有していました。もしこのスペック差に気付いてないと、3台への振り分けをする際に苦しむことになったかもしれません。
  • 競技サーバー1: 1 GB RAM, 2 vCPUs
  • 競技サーバー2: 2 GB RAM, 2 vCPUs
  • 競技サーバー3: 1 GB RAM, 4 vCPUs

今回はサイバーエージェント様のプライベートクラウドを利用させていただいたので、このように柔軟なリソース割り当てができ、とてもありがたかったです。いわゆるオンメモリ戦術が有利になりすぎないようメモリを少なめにしていましたが、実際のところ 1 GB はきつすぎたようで、ちょっと無理をするとサーバから応答がなくなってしまうような状況にありました。また今回は高い並列性が求められる問題だったこともあってメモリの少なさが言語の差がつく原因の一つになっていたようで、ここに関しては申し訳なく思います。

静的ファイル配信

ISUCON10 本選の実ベンチマーカーは Web ブラウザを模した挙動をするように作られていました。 ISUCON10 のために rosylilly が開発した isucandar というベンチマーカーフレームワークを利用しています。

isucandar は取得した HTML の link 要素、script 要素を解釈し、含まれている外部リソース(css, js)へのリクエストを行います。また、 favicon.ico へのリクエストもいちいちしてくれるのでリアルです。実ベンチマーカーからのアクセスログをじっくり読まれた方は、そのリクエスト群の「それっぽさ」を味わっていただけたかと思います。
初期状態では上記のような静的ファイル(css, js, favicon.ico, HTML)へのリクエストもアプリケーションで捌いてる状態になっているので、これを前段に nginx 等を置くなどすることでアプリケーションの負荷を下げることができます。

実ベンチマーカーはリクエストの際に Accept-Encoding: gzip, br, deflate のリクエストヘッダを送っていました。静的ファイルのリクエストはネットワーク帯域を考えるとそれなりに無視できない量があったはずで、nginx 等を用いて static gzip の設定をするか、実は対応していた brotli にしてあげるとかなり転送量を抑えられたかと思います。オススメは(せっかく対応したので) brotli でした……が気付いたチームはいたんでしょうか。また、マニュアルにわざとらしく書いてあるとおり実ベンチマーカーは Cache-Control に対応しているので、 max-age を設定すれば静的ファイルへのリクエスト自体を減らすことができます。仮想オーディエンスは増えるたびに新しいブラウザセッションで訪れてきてそのたびに静的ファイル配信はどんどん増えていくため、これらのような対策をしていないと次第に大きなトラフィックになっていったはずです。

SQL

提供された競技サーバーでは MySQL 8.0 が動いており、アプリケーションから利用されていました。初期状態ではこれといったスロークエリは無く、スロークエリログを有効にして張っていてもほとんど出力されなかったと思います。今回の問題では、初期状態ではすべてのテーブルは空の状態から実負荷走行が始まります。そのなかでテーブルに書き込みが走っていくので、初期状態ではアプリケーションのスループットが低くテーブルのデータがあまり増えないため、データ量起因のスロークエリが起こり始めるのはチューニングが進んだ実競技後半になるとおもいます。

そのかわり、N+1 や、本来叩く必要の無いクエリが意図的に随所に仕込んであります。一つ一つは 1ms 前後で返されるようなものですが単純に量が多いため、これらのクエリが発生しないようにアプリケーションを変えていく必要があります。
たとえば、仮想コンテストの開催時間を管理する contest_config テーブルは、/initialize 以降は更新されることがないので、負荷走行の中ではずっと使い回すことができます。
また、contestants や teams テーブルは、仮想チーム登録フェーズが終わった後は更新されることがないので、使い回すことができます。これらを protobuf にエンコードする頻度は高いため、protobuf にした状態でキャッシュしておくのもいいと思います。

ダッシュボード(Leaderboard)

実負荷走行の中でダッシュボードページは高い頻度でアクセスされますが、重い集計処理が走るようになっているので、これはチューニングが重要になってきます。

02
図2: ダッシュボードの Leaderboard 部分

ダッシュボードの Leaderboard 部分の集計は69 行もある 1 つの SQL クエリで実装されており、多くの方は見た瞬間に嫌気が差したかと思います(mirakui の力作です!)。このクエリはデータ量(仮想負荷走行の実行回数)の少ない初期状態ではスロークエリではないですがチューニングが進むと重くなっていくので、手を打っておく必要があります。対策としては

  • 仮想負荷走行が完了したときにあらかじめ Leaderboard のデータを作っておく
    • このデータ更新を同期的に行うとボトルネックになるので、非同期である程度まとめて処理するのがおすすめ(report_benchmark_job の ack は更新完了まで返さない)
  • student flag や latest / best score をカラム化しておくとよい
などが有効だったかと思います。

ダッシュボードにアクセスするのは仮想選手と仮想オーディエンスなのですが、仮想オーディエンス向けダッシュボードのみ、最大 1 秒のキャッシュが許可されていました。この 1 秒の判定はシビアで、単に1秒キャッシュをしているだけだと、アプリケーションが詰まり始めたときに「仮想負荷走行の結果が 1 秒以内にダッシュボードのレスポンスに反映されている」が達成できなくなる場合があったかと思います。このときに出力される「期待より古い内容のリーダーボードが返却されています」というエラーに悩まされたチームも多かったのではないでしょうか。
仮想オーディエンス向けダッシュボードのキャッシュについては、アプリケーションに対して同時に複数のキャッシュ更新(Thundering Herd)が走らないようにしたり、非同期でキャッシュ更新を走らせるようにしたりするのが効果的だったかと思います。たとえば Go の singleflight や Varnish を使うことでこういった制御をする事が可能です。

通知の Web Push 化

03
図3: ダッシュボードの通知機能

今回の問題では、仮想選手たちが高頻度で通知のエンドポイントをポーリングし、新着通知(仮想負荷走行の終了通知、質問仮想運営からの回答通知)を取りに来ます。今回の実ベンチマーカーは Web Push サーバーを内蔵しており、アプリケーションからの通知を Web Push 通知に実装し直すことで、ポーリングの処理を軽減できるというギミックがありました。Web Push 方式への書き換え方については、各言語でのサンプルコードを用意し、あまり高い障壁にならないように配慮していました。実ベンチマーカーへの Web Push サービスの実装は(sorah が)頑張って実装したのでぜひ使って欲しかったですが、参加者の多くは実装しなかった、あるいは実装したけどスコアが下がったのでポーリング方式に切り戻した、というご意見が多かったような印象です。実は、単にすべての状態の変化を即時に仮想選手に Web Push 通知するだけだと、仮想選手達は同時かつ即時に次のリクエストを送ってきていわゆる Thundering Herd 問題が発生し、より瞬間的な負荷が高まってしまうという状況が予想されるからです。

この状況の対応として想定していた回答の一つは、全体通知(Clarifications への回答は全選手へ同時に通知する場合がありました)については Thundering Herd 問題を避けるためにポーリング方式で処理し、それ以外の個別通知は Web Push 方式で処理する、というものです。実ポータルでは実際にそういう実装にしてありました。本選競技中になかなかそこまではしないだろうなーと思いつつも、やりこみ要素の一つとしてご理解いただければと思います。

白金動物園による解答例

本選と同じスペックの競技サーバー 3 台をお借りして sorah が解いたところ、以下のようなスコアになりました。
  • 使用言語: Ruby
  • スコア: 36,768
おもにやったことは以下の通りです(順不同)。

  • ミドルウェアの導入: nginx, Varnish, Redis
  • 最終的な競技サーバー 3 台の役割: server 1 で実負荷走行を受け、 Envoy で3台に振り分け
    • server 1 (1GB, 2 vCPUs): Varnish, 静的ファイルの配信 (nginx), benchmark_server (gRPC)
    • server 2 (2GB, 2 vCPUs): web のうちスコアに寄与しないもの, MySQL, Redis
    • server 3 (1GB, 4 vCPUs): web のうちスコアに寄与するもの, benchmark_server (gRPC)
  • 静的ファイル配信
    • nginx + static brotli
    • Cache-Control (expires 1d;)
  • receive_benchmark_jobs (gRPC)
    • benchmark_jobs のキューを Redis 化し、sleep つきループの代わりに BRPOP でジョブのエンキューを待つようにした
  • ダッシュボード(仮想選手&仮想オーディエンス)
    • 仮想負荷走行が成功したときにあらかじめ Leaderboard を構築し、都度 Redis に保存するようにした
    • 負荷軽減のため Leaderboard はアプリケーション側で計算するようにし、例の巨大な Leaderboard SQL は廃止
    • Leaderboard の更新負荷を下げるため、時間の近い (0.3s 以内の) 複数の report_benchmark_jobs (gRPC) を待ち合わせてLeaderboard 更新を 1 回にまとめるようにした
    • 仮想オーディエンス向けダッシュボード
      • Cache-Control: public, max-age=1
      • Leaderboard から生成した ETag を付与
      • varnish でキャッシュ (ttl=0.5s, grace=0.2s)
  • 各種 N + 1 の解消, MySQL index の改善
  • カウンタキャッシュ等の導入
    • teams.student, teams.last_answered_clarification_id
  • 通知の Web Push 化
    • (Ruby のため) Envoy で HTTP/2, TLS を終端し接続処理の負荷軽減も併せて実施
    • Web Push の購読がある場合、 GetNotifications では通知を返さないように
  • Puma 4 -> 5
    • 9/17 にリリースされていた
    • 4 ->5 でのパフォーマンス改善 (wait_for_less_busy_worker で負荷の低い worker にリクエストが行くようになる等) や nakayoshi_fork によるメモリ使用量削減効果を期待
  • 参加仮想チーム数の引き上げ
    • 最高スコア時は TEAM_CAPACITY=65
  • gRPC server (griffin) や Puma の workers, threads 調整
    • 併せて envoy の max_concurrent_streams を調整して gRPC server の最大同時リクエスト数を考慮してロードバランスするように


講評

今回の本選問題はあのシンプルな予選問題とは打って変わってとても参考実装のコード量が多く(移植チームの皆様本当にありがとうございます!!!)、またマニュアルもそれなりにボリュームがあったため、全体を把握するだけで多くの時間が取られてしまったチームは多かったのではないでしょうか。また、protobuf / gRPC や Web Push、Envoy など、これまでの ISUCON に登場しなかった技術要素も登場し、これらに馴染みのないチームは頭を抱えたかもしれません。

実競技の前半は、これまでの ISUCON でも活躍してきたベテランのチームがスコアを大きく伸ばし、上位を占めていた印象です。今回の問題は最初からアプリケーションネックの状態から始まるので、複数のサーバにうまく負荷を振り分けたり、静的ファイルの負荷がアプリケーションに行かないようにしたりなど、アプリケーションコードではなくインフラの技術によって大きくスコアを伸ばせる状態だったため、サーバのリソースと相談しながらこういったチューニングを素早くできるような、経験のあるチームが有利な展開だったかと想像します。

アプリケーションの解読が進んで各チームが具体的なアプリケーション改善に取り組み始めたであろう後半では、やはりパフォーマンスチューニングの基本である、今のボトルネックを正しく計測・理解し、改善していくサイクルを精度良く回せていったチームが上位に上がっていったのだと思います。参考実装のコード量が多く、視界に入ったものを推測で改善するのではなく、やることをうまく絞っていく必要があるからです。例の巨大な Leaderboard の SQL はそのためのちょっとした仕掛けのひとつでした。経験のあるエンジニアほどあのクエリを見たら真っ先になんとかしたくなると思いますが、先に改善するべきボトルネックは他にあります。

最終的に 1 位から 3 位まで学生チームが占め、しかも 1 位は 1 人チームだったという、これまでの ISUCON の常識を覆す結果となりました。記念すべき 10 回目となる ISUCON がこのように新しい時代を感じさせる象徴的な結果となり、それに立ち会うことができたのは問題作成者の一人として誇らしく思います。

最後に、ISUCON10 の予選や本選に参加していただいたチーム、スポンサーをしてくださった企業の皆様、ISUCON10 を応援し盛り上げてくださった全ての人に感謝申し上げます。
Read more...

こんにちは、運営の櫛井です。
10月13日に放送した ISUCON10 アフターイベントご視聴・ご参加いただきありがとうございました!
放送の中で行なったISUCONクイズ(通称ISUCONカルトクイズ)は、80名ほどの方にリアルタイムにご参加いただき大変盛り上がりました。AhaSlidesというツールを利用しましたが、参加者が同時に参加できる楽しさがありオススメです。
ididi


結果は、本選と同じくtakonomuraさんの優勝となりました。完全制覇おめでとうございます!
isucon quiz

ISUCONカルトクイズがなかなか好評だったので、設問・選択肢・正解率を共有させていただきます。皆さんは何問わかりますか?

Q.1 ISUCONに予選という仕組みが始まったのはいつから?
 (100点 正解率 61%)
 A. ISUCON1
 B. ISUCON3
 C. ISUCON5
 D. ISUCON7

Q.2 競技時間8時間のうち、自チーム以外のスコアランキングが更新されなくなるのはいつ?
 (100点 正解率 96%)
 A. 残り4時間
 B. 残り2時間
 C. 残り1時間
 D. 残り30分

Q.3 ISUCON1の優勝賞金は?
 (100点 正解率 6%)
 A. 100万円
 B. 50万円
 C. 10万円
 D. 6万円

Q.4 エンジニアHubのインタビューでISUCON10の本選出題担当である白金動物園が語った「学生が強くなったのは◯◯を手に入れたから」 正しいのはどれ?
 (200点 正解率 30%)
 A. (ブログなどの)情報を手に入れたから
 B. (擬似的な)負荷を手に入れたから
 C. (相対的に)時間を手に入れたから
 D. (物理的な)練習場所を手に入れたから

Q.5 ISUCONに学生枠が初めて設置されたのはいつ?
 (100点 正解率 10%)
 A. ISUCON3
 B. ISUCON5
 C. ISUCON8
 D. ISUCON10

Q.6 ISUCON8で優勝した学生チーム「最大の敵は時差チーム」の3人が参加したのは東京、海外、あと一人はどこから?
 (100点 正解率 9%)
 A. 東京
 B. 神奈川
 C. 埼玉
 D. 千葉

Q.7 本選問題の動画で表示されていたX41さんはどれ?
 (100点 正解率 70%)
abc




Q.8 ISUCON 夏期講習 2020で講師のrosylillyさんが伝えた「チームの???を確保しよう」 正しいのはどれ?
 (100点 正解率 75%)
 A. TPO = Time(時間) Place(場所) Occasion(場合)
 B. KPI = Key Performance Indicators(定量的な指標)
 C. bps = bits per second(データ転送速度)
 D. HRT = Humility(謙虚)  Respect(尊敬)  Trust(信頼)

Q.9 ISUCON10の準備期間中、運営の941さんがハマっていたゲームは何?
 (100点 正解率 9%)
 A. ゼルダの伝説 ブレスオブザワイルド
 B. Ghost of Tsushima
 C. スプラトゥーン2
 D. ポケモン 剣盾

Q.10 ISUCON10 本選ライブアンケートの結果で「複数回答あり、面白かったコンテンツ」2位になったのはどれでしょう
 (100点 正解率 53%)
 A. mirakuiさんのパンの話
 B. 本選出場33チーム紹介
 C. 並行チーム企画
 D. 本選問題発表

Q.11 ISUCON4はどれ?
 (100点 正解率 26%)
1234



Q.12 エンジニアtypeのインタビューでISUCON10インフラ担当 サイバーエージェントの中西さんが語った「ISUCONに惹かれたところ」は?
 (200点 正解率 23%)
 A. アドレナリンが出るところ
 B. 終わったあとの感想戦が楽しいところ
 C. 打ち上げが楽しいところ
 D. 実務にすぐ活かせる技術力が身につくところ

Q.13 社内ISUCONを最初に開催したのはどの会社?
 (100点 正解率 48%)
 A. 株式会社リクルート
 B. ウォンテッドリー株式会社
 C. 株式会社モバイルファクトリー
 D. 面白法人カヤック

Q.14 Qiita ZineのインタビューでISUCON10 予選出題担当の古川さんがISUCONについて語った「限られた◯◯の中で◯◯を出すことは難しい」で正しいのはどれ?
 (300点 正解率 66%)
 A. 限られた時間の中でパフォーマンスを出すことは難しい
 B. 限られたリソースの中で結果を出すことは難しい
 C. 限られた予算の中で景品を出すことは難しい
 D. 限られた可処分所得の中で新しいパソコンの費用を出すことは難しい


参考までに、優勝したtakonomura氏は14問中11問正解したとのことです。

正解はISUCON10 アフターイベントのアーカイブからどうぞ
Read more...

ISUCON10 予選において発生していた、競技開始の遅延をはじめ、ベンチマーカーの不具合、ポータルの 50x エラー等、度重なるトラブルについて詳細を説明させていただきます。

運営チーム一同として、様々な要因から複合的なトラブルに発展させてしまったという認識です。これらの反省点を踏まえ、同種のトラブルを起こさぬよう、次の運営チームへ反省点やデータを引き継いでいきたいと考えています。その観点において、以下に ISUCON10 予選で発生していた各種トラブルの背景・原因について振り返ります。

競技時間の延期について

まずは ISUCON10 予選の競技時間が、当初予定の 10:00 開始から 12:00 、さらに延期して 12:20 となった件について説明します。

これは、競技環境のサーバーの展開作業 (全台作成/デプロイ) が想定を大幅に超える時間を要した事が直接的な原因です。VM (仮想マシン) のディスクイメージ完成の遅延が根本原因と言えますが、下記で順を追って解説します。

インフラ環境および作業の流れ

ISUCON10 では、サイバーエージェントさまのインフラを利用して予選・本選ともに競技を実施しました。サイバーエージェントさま ("インフラチーム") よりストレージ・サーバーといった物理的資源に加え、今回の ISUCON10 向けの仮想環境基盤 ("クラウド基盤") の提供があり、その上に競技環境を構築、選手へ提供されました。

展開作業までの流れとしては、以下の通りです:

1. 一般的な VM (仮想マシン) のイメージである qcow2 ファイルを作問チームが作成 (必要なソフトウェアやソースコードはこの時点でセットアップ)
2. インフラチームへ引き渡し
3. インフラチームが作問チームのリクエストしたスペック・台数で VM を展開
4. 展開された VM は cloud-init を利用して選手の SSH 公開鍵を ~isucon/.ssh/authorized_keys に登録する等、チームごとの初期化処理を自動で行う

VMイメージ完成の遅延

予選に際しては、まず予選作問チーム側の要因として、最終版となるマスターイメージの完成が競技前日の 23 時となっていました。本来であれば早期に確定できるはずでしたが、言語移植作業の遅延等で、完成が遅れていました。

また、マスターイメージを利用しての検証作業も、競技前日の完成となってしまっていたため不十分でした (後述します)。

展開作業の遅延

そして、インフラチーム側の要因として、マスターイメージ展開作業まで要求されたスペックでの全台展開作業を実施しておらず、予選前日まで展開作業にかかる時間が理論値で見積られていたこと、そして、予想しない問題により、実際の展開作業中に VM の展開速度が低下していったことが挙げられます。

インフラチームでは、VM を動作させるハイパーバイザーとなるサーバー (HV) が 24 台用意されていました。そして、HV 1 台に割り当てた VM を展開するのに要する時間を事前に調査しており、その単純な 24 倍を展開作業時間の理論値として見積っていました。
なお、競技環境については、選手用の 3 台、ベンチマーカ用の 1 台、SSH 踏み台 (冗長構成) 2 台でチームあたり計 6 台の VM により構成され、計500チーム分の用意で3000 VMになります。

そして、競技前日 23 時に完成した予選マスターイメージについて、23 時からの展開作業はバッファは微妙でも間に合うだろうと開始していました。しかしながら結果として、途中ストレージアプライアンスにおいてイメージのコピーに要する時間が徐々に遅くなっていくという問題が発覚し、競技開始の 10 時に全チーム分の VM が起動していないという事態に発展しました。

ここに関しては、まず「マスターイメージ完成の遅延」で後続作業のバッファを食い尽くしてしまっていた事に加え、事前の全台展開作業の検証不足が後押しした形となり、結果として競技時間の遅延を招いてしまいました。

なお本選においては、これを踏まえイメージ作成 (packer build) を CI 化することにより、作問チームとコミュニケーションをせずに継続的にインフラチームへ本選 VM イメージが引き渡される状態になっていました。そして、完成前より全台展開の試験を行って未然の問題を検知していました。また、インフラチームにおいても展開作業の遅延につながったストレージアプライアンスの問題について事前に対策を行うことで、問題なく展開作業を前日までに済ませる事が出来ました。

また、予選で提供した VM についてはいくつかのチームにおいて SSH ログインが不可能、もしくは何らかファイルシステムが破損しているケースが存在しました。これらについての原因は明らかにはなっていませんが、余裕を持った検証作業を行うことで、本選においては問題ない状態で提供することができていました。

競技開始直後 - 13:00 までベンチマーク実行ができなかった件

競技開始後 40 分の間 (12:20-13:00)、ベンチマーク実行ができなかった件について説明します。端的には、競技開始から 13:00 までの間、ポータルに競技環境のサーバ情報が登録されていなかった事が原因です。インフラチームよりポータルへデータが登録されることになっており、クラウド基盤からポータルへのデータ送信は半自動化されていましたが、送信作業が実施されていませんでした。

前述のように、競技環境の展開作業が前日 23 時から夜通しの作業となっており、インフラチームは競技開始時点で体力の限界を迎えていました。運営チーム全体としても、展開が終わった VM の確認作業などで競技開始直前はかなり余裕がない状態で、この点において確認を怠ったまま競技を開始してしまいました。

その後、インフラチームが存在しないサーバーデータについて、準備をし 13:00 に登録作業を実施したことによりベンチマーク走行が可能になりました。なお、この遅延を受け、競技終了時間を 20:20 から 21:00 に延長しました。

14:00-14:45 頃ベンチマーカーが停止していた件

ベンチマーカーが 14:00-14:45 頃に停止していた件について説明します。簡潔には、ベンチマーカーの設定ミスを修正しようとした所、再起動後に開発環境へ接続してしまう別の問題が発生しました。その問題の修正にオペレーション上の問題で時間を要し、結果として 45 分間ベンチマーカーが停止する事態になりました。

順を追って説明します。

ベンチマーカーサーバーの構成について

ISUCON10 のベンチマーカーサーバーは、ポータルチーム (本選作問チーム) が用意したポータルと通信する supervisor と、作問チームが用意するベンチマーカーバイナリによって構成されていました。

ポータルチームは作問チームの作るベンチマークサーバーの VM イメージについては携わっておらず、事前に supervisor を起動するためのsystemd unit ファイルの例示のみを行いました。

そして、supervisor が取る設定値に hard timeout があり、これは supervisor が一定時間以上動作しているベンチマーカープロセスをタイムアウトとして kill(2) する際の閾値を設定します。参考値として 70 秒を提示していましたが、実際の予選ベンチマーカーの挙動に合わせ調整がなされておらず、この修正が必要になっていました。実際、競技開始時~14:00 までの間、ベンチマーカーが強制終了されて負荷走行が ERRORED になってしまうケースをいくつか確認しています。

この設定ミスについては、ポータルチームから supervisor の設定について能動的なレビューを実施しなかったこと (また予選作問チームよりレビュー依頼もありませんでした)、さらに予選作問チーム内でベンチマーカーの最大動作時間について確認を怠ったことが原因です。また、後述する不十分なテスト体制により、事前に問題として検知されることもありませんでした。

ベンチマーカー停止の経緯

そして、本設定ミスを修正する際、クラウド基盤の metadata が意図せず入れ替わり supervisor の接続先が本番環境から開発環境へ切り替わってしまいました。

接続先ポータル情報については VM イメージ内に含まず、metadata サーバーから取得することで、開発環境および本番環境の切り替えを達成していました。実際に 予選ベンチマーカーサーバーで稼動していた supervisor の systemd unitでは、ExecStartPre= でクラウド基盤が提供する metadata から接続先ポータル情報を取得、systemctl(1) の set-environment を実行してから ExecStart= で supervisor を起動するという設計になっていました。

この副次的なトラブルを解決するにあたり、ポータルチームはインフラチーム、予選作問チームと連携し対処を試みましたが、ポータルチームがベンチマーカーサーバーを含む予選の競技環境へログインする手段を準備していなかったこと、また予選作問チームが約 500 台あるベンチマーカーサーバーに対するオペレーションについて事前の想定が甘く、修正作業の実施に時間を要しました。

最終的に metadata サーバーから値の取得を ExecStartPre= で実行しないように修正、また手動で正しいデータを設定することで 14:45 頃に復旧しました。本選においては、サーバー起動時の 1 度のみ、別 systemd unit で metadata を取得する設計であったため、同様の問題は起こらない状態となっていました。

ポータル側のメトリクスを根拠として、本事象は全チームのベンチマーカーサーバーで発生したものと考えられます。たとえ一部チームでは発生していなかったとしても、本事象の発覚から即座に全ベンチマークサーバーのサービスを明示的に停止したため、チーム間で事象の発生時間に差は生じていません。

なお、競技時間が既に開始を含め変更を重ねており、競技時間終了を 21:00 より遅くすることは選手・運営ともに許容されないだろうという判断から、本件を受けての競技時間の延長や補填は実施しませんでした。

ポータルが重く繋がりづらかった件

特に 15:00 以降、ポータルが重く繋がりづらかった問題について説明します。端的には、ISUCON10 予選のトラフィック量にポータルが考慮不足で耐えられなかった事が原因です。

まず前提として、ここしばらく ISUCON の予選は土日いずれか選んで参加する 2 日開催となっていました。今回の ISUCON10 予選は 1 日での開催となり、参加チームの規模はこれまでと大差ないため、これまで 2 日に分かれていたポータルへのトラフィックが 1 日の競技時間中に全てやってくると言えます。

ポータルチームでは、事前にダミーのベンチマークジョブ・結果を生成しパフォーマンステストをしていましたが、実際には想定の 2 倍のトラフィック、またベンチマークジョブ数についても想定の 2.5 倍以上あり、パフォーマンス上の問題が生じていました。

ISUCON ポータルサイトは大会規模が大きくなるにつれ、しっかりと考慮しないとリクエストを捌ききれないレベルになっています。その点において、ISUCON10 ポータルチームでは想定・準備不足だったと言わざるを得ません。しかしながら、確実に対策するためのデータが十分だとは言えない状況です。そのため、ISUCON10 ポータルチームではリクエスト傾向や実際のベンチマークジョブのデータを保存し、次回以降の開催に活かせるようにします。

  • 実際のリクエスト傾向: 最大 560 rps (CDN で 120 rps ほど吸収)
  • 実際のベンチマークジョブデータ: 全 27572 件


  • 本選では予選で不要だと考えていたキャッシュの導入などを進め、同種の問題は起こりませんでした (そもそも予選に比べトラフィックが少ないという違いは存在します)。

    ベンチマーク (負荷走行) における複数の問題について

    最後に、競技時間中に発生していたベンチマーカーに存在する複数の不具合と、そこから派生したトラブルについて説明します。なお、競技中に 1 件明確な SIGSEGV について 修正を行いました が、その修正に関しては割愛します。以降で述べる不具合については、競技時間中の修正をせず、競技時間後、追試前に workaround を実装して回避しています。

    主にベンチマーカーおよび前述の supervisor からポータルとの間に問題が生じていました。複合的な不具合とトラブルであったため、まずはベンチマーク実行から完了までの流れから説明します。

    1. 選手や運営がポータルへ負荷走行 (benchmark job) を enqueue
    2. supervisor がポータルから job を receive
    3. supervisor がベンチマーカーを起動
    4. ベンチマーカーが supervisor に結果データ (BenchmarkResult) を送信
    5. supervisor がポータルに (4) で受け取った BenchmarkResult を送信
    6. (4)-(5) を繰り返し、ベンチマーカーが終了
    7. supervisor がポータルにベンチマーカーの stdout, stderr ログを含めた BenchmarkResult を送信し、実行完了を通知
    8. ポータルが job のステータスを FINISHED (もしくは ERRORED) に変更、選手へ通知

    このうち、ポータルsupervisor(4) の supervisor へ結果を送信するライブラリ (+ そのサンプルコード ) についてはポータルチームで用意していました。

    ベンチマーカーおよびポータルの根本的な不具合について

    不具合の根本原因から説明します。

    ベンチマーカーからも stdout, stderr が supervisor に送信されていた
    上記手順の通り、ベンチマーカーの stdout, stderr は supervisor によって取得され送信されていました。したがって、ベンチマーカーは詳細なログを自ら supervisor に送信する必要はなく、通常の stdout/err へ出力すれば良いという設計でした。
    その前提で、supervisor との通信の仕様として 65,535 bytes が 1 メッセージのサイズ上限となっていましたが、stdout/stderr フィールドに多量のデータが入っていることによって、supervisor へメッセージを送信できずエラーとなるケースが発生していました。

    これが起きた原因として、ベンチマーカーより supervisor へデータを送信する際に利用する struct は実際に supervisor がポータルへ送信する際も利用する protobuf message のものと全く同じものを採用していた事が考えられます。したがって、stdout/err といったベンチマーカーが直接利用する必要のないフィールドも残ったままとなっていましたが、サンプルコードにおいて 利用する必要がない旨 明示していました。ポータルチームも supervisor との連携コードにおいて レビューに呼ばれていました が、この点を見落したまま予選を迎えました。

    なお、この不具合が特定されたのは予選競技終了後の workaround 実装時です (workaround については後述します)。

    supervisor がベンチマーカーのログを取得する際の truncate 処理において UTF-8 の想定がなかった
    supervisor がベンチマーカーよりログを取得する際、長すぎるログについてはその全てを送信しないよう、末尾 48,000 bytes のみ送信するようになっていました。

    日本語を含まないログでのみテストしていた、かつ、日本語が来る事をポータルチームでは想定漏れをしていて、後続の処理で invalid UTF-8 sequence といったエラーが生じてしまう状態になっていました。(本選前に修正 しました)

    他のトラブル同様、全体を通してのテストが十分であれば事前に特定できていた不具合だと考えられます。

    ポータルが supervisor より大きいメッセージを受け取る際、稀にポータル側でエラーが出てしまう状態だった
    supervisor より送信される長い stdout, stderr ログを含んだ結果のメッセージについて、サーバー側の gRPC プロトコル実装にバグがあり、稀にサーバー側でエラーが発生していました。これについても本選前に修正し、その修正を含むパッチ が提出されています。

    こちらも他のトラブル同様、全体を通してのテストが十分であれば事前に特定できていた不具合だと考えられます。

    競技時間中に不具合によって発生していた事象について

    以上の不具合の結果、下記の事象が発生していました。

    負荷走行は正常に終了するが、stdout が空でエラーの詳細が分からない
    エラー詳細などを含むメッセージを最後に stdout に出力しており、supervisor への結果送信に失敗した際、処理が中断されることで空の stdout となるケースが発生していました。その場合でもエラーは棄却されベンチマーカーは正常終了してしまっており、運営がテスト中および競技時間中、問題として認識することができませんでした。

    具体的には、負荷走行の結果 stdout/err に多量のログが出力されていた場合、「ベンチマーカーから supervisor へ stdout/err に出力した同内容が送信されていた」ためにメッセージ長が容易に 65,535 bytes を超えてしまい、最終的な結果送信がエラーとなっていたが、そのエラーが棄却されていた事が原因であると推察されます。

    ポータルチームより提供していたライブラリは、メッセージ長上限を超えた場合は エラーを返却 するようになっていました。予選ベンチマーカーでは当該エラーについて予選ベンチマーカー内で 処理を中断するようハンドリングしていましたが最終結果送信時のエラーについては全て無視 していたことにより、例外として発覚しませんでした。

    そして、当該エラーの発生が stdout への原因等出力の前であったため、ログが一切出力されないまま、失敗だけが選手へ通知される事象に繋がりました。そして、stderr が別途一定量を超えている場合は、次に説明する別の問題が発生していました。

    この事象が発生したと見られるベンチマークジョブは 27572 ジョブ中 1546 ジョブを確認しています。

    ベンチマークジョブ (負荷走行) が RUNNING のまま終了しない
    エラー1つあたりに対して発生する予選ベンチマーカーのログ (選手に開示されない stderr 含む) が非常に多かったため、特に負荷走行対象が多量のエラーを発生させる状態の場合、前述のログ量に関する問題が発生しやすい状態でした。ログ量に関する不具合が起きた場合、ポータルへ正常にジョブ結果が登録されず、RUNNING のままになってしまう事象となります。

    そして、ポータルとの通信でエラーが発生した時、数回に渡ってリトライするようになっていましたが、不具合が発生する時は 1 度も成功することなくリトライ上限に達していました。

    当該ジョブについては、競技時間中の対応として選手側で追加の enqueue を可能にするため、運営側で CANCELLED あるいは ERRORED のステータスにバッチあるいは手動で変更していました。この影響があったジョブとして 27572 ジョブ中 1808 ジョブを確認しています。なお、アドホックな対応だったため、時間帯によってキャンセル基準が不揃いとなっていました。

    本選では予期せぬ不具合があった場合でも自動でベンチマークジョブを完了させられるよう、supervisor でエラーが発生した場合は supervisor がエラーで終了するように変更、また supervisor 起動時に当該 supervisor が取得していたジョブを全てエラー状態へ変更するロジックを導入しました。なお、本選においては、本選中に実施した不具合修正のためのデプロイで発生した supervisor のエラーを当該ロジックでキャッチすることができていました。

    追試の際に実施した workaround について

    予選結果 で告知している通り、運営による追試は上記の不具合を回避する状態で実施しました。具体的には、下記の workaround を実装して実施しています。

  • 予選ベンチマーカーから supervisor へ送信するメッセージの stdout/stderr フィールドを送信しない (supervisor 設計の意図通りにする) https://github.com/isucon/isucon10-qualify/pull/170/commits/2eb24446e0538a9e212ebde3c1f30adeb88ee9c5
  • supervisor がベンチマーカーを起動する際、
    exec path/to/benchmarker "$@" > ~/bench.$$.out 2> ~/bench.$$.err
    のようなシェルスクリプトを経由するように変更し、supervisor が一切ログを取得しないようにする


  • 前述までの通り、競技時間中に複数のトラブルが起きていた事や、ベンチマーカーサーバーのオペレーションにおいて更なるトラブルを招いてしまった事から、ポータルチームの判断として、上記 workaround を競技時間中に実装することはせず、競技時間後、追試前に実装する事にしました。

    また、予選結果における「ベンチマーカーの不具合による本選出場チーム」については、競技時間内に最後に正常に完了した負荷走行 (= ステータスが FINISHED であるジョブ) でスコアが 0 点と記録されているが、競技時間内の最後のジョブが ERRORED, もしくは CANCELLED となっている (= 正常に完了しなかった) チームについて、追試において記録されたスコアを検討しました。なお、「FINISHED であるが不具合で 0 点となってしまうケース」に関しては、判明している不具合や、競技時間内での対応では発生しません。

    ベンチマーカーの不具合に際して、特に「スコアが出ない」「fail となってしまう」チームにとって原因特定が困難である、いわゆる「体験が悪い」状況を作ってしまったと理解しています。そして、これが予選競技の中で最も起こしてはならない類のトラブルに発展してしまった事について、運営チームは重く受け止めています。次回以降の ISUCON 運営チームに、トラブルの原因や反省点について引き継いでまいります。

    不具合の発生、および未然に気付けなかった原因について

    以上の通り、競技時間中は複数のトラブルが発生していました。そのため、いくつかのトラブルや不具合については繰り返しとなりますが、競技時間中の修正を諦めています。

    この他にも、インフラチームのセキュリティ要件から SSH 公開鍵認証や SSH 踏み台が必要となっており、関連するサポート依頼に対し運営側の不備でないかの切り分けなどに運営チームのリソースが割かれていた事から、各種対応において不手際や遅延が目立つ状況になっていたと考えられます。

    テストの不備

    特に競技開始の遅延やベンチマーカーの不具合に関しては、徹底的なテストの不備が原因だと挙げられるでしょう。最終的にポータルの開発環境と予選ベンチマーカー・競技環境を接続してのテストは最低限行われましたが、実際に選手が取る行動を模したテストはされておらず、ログ量で再現する問題を予選までの間に発見することはできませんでした。

    そして、イメージの完成遅延があり、テストを十分な時間、十分なメンバーで実施しませんでした。振り返りとして、完成途中のイメージを利用してでも、事前に全台展開のテストや、それを用いてのテストコンテストを運営で開催し、実際の最終形となったベンチマーカーを用いて予選問題に運営内の複数チームで取り組んでみる、といった試験のスケジュールを予め決めておき、実施するべきだったと考えています。開発環境で全てテストできる状態を出来るだけ早期に満たし、継続的にベンチマーカーを含め更新できるのが最善でした。

    根本的な要因

    徹底的なテストや、競技時間中の不具合修正を妨げた要因としては、主にスケジュール・コミュニケーション・オペレーション上の 3 つが挙げられます。

    まず、参考移植やイメージ作成、展開作業、テストといった直前の作業について、予選競技日までに何が必要か、物理的なデッドラインというところを含め、スケジュールやマイルストーンについて運営チーム内でのコンセンサスが不足していました。ここから、展開作業などのバッファや、必要な期間の認識に作問チーム・インフラチームの間でズレが生じていたと考えられます。

    そして、コミュニケーション面での問題について。はじめに、運営内でも複数の企業間で役割が分担されており、遠慮・プレッシャーを与えない配慮なども相俟ってチーム間のコミュニケーションが不足していた点も問題だったと言えるでしょう。それぞれに余裕がなくとも、チーム間で能動的に進捗確認や、最終的な試験を実施するデッドラインの定義、またそれを受けた代替案などを考える、といったことを遠慮せずに行うべきでした。

    また、ポータルとベンチマーカーの通信部分に関しても、最低限のドキュメントやサンプルコードのみを渡し連携していましたが、わからないことがあれば質問がくるであろうという強い仮定で予選まで進行してしまいました。結果として、誤った利用方法から不具合に繋がりました。

    最後にオペレーション上の問題について。予選ではおよそ 500 チームが参加、500 台のベンチマーカーサーバー、そして選手に提供する 1500 台のサーバーと規模の大きな競技環境を管理する必要がありました。
    ベンチマーカーの無停止での入れ替え、万が一の時の非定型な一斉のオペレーションについて、十分に準備がされておらず、またそれを複数人が出来る状態ではありませんでした。そのため、競技時間内にできる対策が限られ、また更なる不具合の発生を防止するため、競技時間内に対策をしない判断が必要となってしまいました。

    最後に

    ISUCON10 予選に参加してくださった選手の皆様には、競技日当日は大変ご迷惑をおかけしました。今回の運営チームはまもなく一旦解散となりますが、次回 ISUCON の運営チームが結成される際には、有用なデータや、今回の ISUCON10 で実施した質問システムといった新しい取り組み、またここで振り返った反省点について、しっかりと引き継いでいきたいと考えております。

    また、ISUCON10 アフターイベントを 10/13 (火) 19:00 よりオンラインで開催予定で、予選・本選作問チームおよびインフラチームが登壇いたします。本エントリで述べた点も含めて予選・本選を通して振り返りをしたいと考えてますので、是非リマインダー登録のほどお願いします。



    Read more...

    ↑このページのトップヘ