ISUCON10 予選において発生していた、競技開始の遅延をはじめ、ベンチマーカーの不具合、ポータルの 50x エラー等、度重なるトラブルについて詳細を説明させていただきます。
運営チーム一同として、様々な要因から複合的なトラブルに発展させてしまったという認識です。これらの反省点を踏まえ、同種のトラブルを起こさぬよう、次の運営チームへ反省点やデータを引き継いでいきたいと考えています。その観点において、以下に ISUCON10 予選で発生していた各種トラブルの背景・原因について振り返ります。
これは、競技環境のサーバーの展開作業 (全台作成/デプロイ) が想定を大幅に超える時間を要した事が直接的な原因です。VM (仮想マシン) のディスクイメージ完成の遅延が根本原因と言えますが、下記で順を追って解説します。
展開作業までの流れとしては、以下の通りです:
1. 一般的な VM (仮想マシン) のイメージである qcow2 ファイルを作問チームが作成 (必要なソフトウェアやソースコードはこの時点でセットアップ)
2. インフラチームへ引き渡し
3. インフラチームが作問チームのリクエストしたスペック・台数で VM を展開
4. 展開された VM は cloud-init を利用して選手の SSH 公開鍵を ~isucon/.ssh/authorized_keys に登録する等、チームごとの初期化処理を自動で行う
また、マスターイメージを利用しての検証作業も、競技前日の完成となってしまっていたため不十分でした (後述します)。
インフラチームでは、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 ログインが不可能、もしくは何らかファイルシステムが破損しているケースが存在しました。これらについての原因は明らかにはなっていませんが、余裕を持った検証作業を行うことで、本選においては問題ない状態で提供することができていました。
前述のように、競技環境の展開作業が前日 23 時から夜通しの作業となっており、インフラチームは競技開始時点で体力の限界を迎えていました。運営チーム全体としても、展開が終わった VM の確認作業などで競技開始直前はかなり余裕がない状態で、この点において確認を怠ったまま競技を開始してしまいました。
その後、インフラチームが存在しないサーバーデータについて、準備をし 13:00 に登録作業を実施したことによりベンチマーク走行が可能になりました。なお、この遅延を受け、競技終了時間を 20:20 から 21:00 に延長しました。
順を追って説明します。
ポータルチームは作問チームの作るベンチマークサーバーの VM イメージについては携わっておらず、事前に supervisor を起動するためのsystemd unit ファイルの例示のみを行いました。
そして、supervisor が取る設定値に hard timeout があり、これは supervisor が一定時間以上動作しているベンチマーカープロセスをタイムアウトとして kill(2) する際の閾値を設定します。参考値として 70 秒を提示していましたが、実際の予選ベンチマーカーの挙動に合わせ調整がなされておらず、この修正が必要になっていました。実際、競技開始時～14:00 までの間、ベンチマーカーが強制終了されて負荷走行が ERRORED になってしまうケースをいくつか確認しています。
この設定ミスについては、ポータルチームから 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 より遅くすることは選手・運営ともに許容されないだろうという判断から、本件を受けての競技時間の延長や補填は実施しませんでした。
まず前提として、ここしばらく ISUCON の予選は土日いずれか選んで参加する 2 日開催となっていました。今回の ISUCON10 予選は 1 日での開催となり、参加チームの規模はこれまでと大差ないため、これまで 2 日に分かれていたポータルへのトラフィックが 1 日の競技時間中に全てやってくると言えます。
ポータルチームでは、事前にダミーのベンチマークジョブ・結果を生成しパフォーマンステストをしていましたが、実際には想定の 2 倍のトラフィック、またベンチマークジョブ数についても想定の 2.5 倍以上あり、パフォーマンス上の問題が生じていました。
ISUCON ポータルサイトは大会規模が大きくなるにつれ、しっかりと考慮しないとリクエストを捌ききれないレベルになっています。その点において、ISUCON10 ポータルチームでは想定・準備不足だったと言わざるを得ません。しかしながら、確実に対策するためのデータが十分だとは言えない状況です。そのため、ISUCON10 ポータルチームではリクエスト傾向や実際のベンチマークジョブのデータを保存し、次回以降の開催に活かせるようにします。
実際のリクエスト傾向: 最大 560 rps (CDN で 120 rps ほど吸収) 実際のベンチマークジョブデータ: 全 27572 件
本選では予選で不要だと考えていたキャッシュの導入などを進め、同種の問題は起こりませんでした (そもそも予選に比べトラフィックが少ないという違いは存在します)。
主にベンチマーカーおよび前述の 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 へ結果を送信するライブラリ (+ そのサンプルコード ) についてはポータルチームで用意していました。
その前提で、supervisor との通信の仕様として 65,535 bytes が 1 メッセージのサイズ上限となっていましたが、stdout/stderr フィールドに多量のデータが入っていることによって、supervisor へメッセージを送信できずエラーとなるケースが発生していました。
これが起きた原因として、ベンチマーカーより supervisor へデータを送信する際に利用する struct は実際に supervisor がポータルへ送信する際も利用する protobuf message のものと全く同じものを採用していた事が考えられます。したがって、stdout/err といったベンチマーカーが直接利用する必要のないフィールドも残ったままとなっていましたが、サンプルコードにおいて 利用する必要がない旨 明示していました。ポータルチームも supervisor との連携コードにおいて レビューに呼ばれていました が、この点を見落したまま予選を迎えました。
なお、この不具合が特定されたのは予選競技終了後の workaround 実装時です (workaround については後述します)。
日本語を含まないログでのみテストしていた、かつ、日本語が来る事をポータルチームでは想定漏れをしていて、後続の処理で invalid UTF-8 sequence といったエラーが生じてしまう状態になっていました。(本選前に修正 しました)
他のトラブル同様、全体を通してのテストが十分であれば事前に特定できていた不具合だと考えられます。
こちらも他のトラブル同様、全体を通してのテストが十分であれば事前に特定できていた不具合だと考えられます。
具体的には、負荷走行の結果 stdout/err に多量のログが出力されていた場合、「ベンチマーカーから supervisor へ stdout/err に出力した同内容が送信されていた」ためにメッセージ長が容易に 65,535 bytes を超えてしまい、最終的な結果送信がエラーとなっていたが、そのエラーが棄却されていた事が原因であると推察されます。
ポータルチームより提供していたライブラリは、メッセージ長上限を超えた場合は エラーを返却 するようになっていました。予選ベンチマーカーでは当該エラーについて予選ベンチマーカー内で 処理を中断するようハンドリングしていましたが 、最終結果送信時のエラーについては全て無視 していたことにより、例外として発覚しませんでした。
そして、当該エラーの発生が stdout への原因等出力の前であったため、ログが一切出力されないまま、失敗だけが選手へ通知される事象に繋がりました。そして、stderr が別途一定量を超えている場合は、次に説明する別の問題が発生していました。
この事象が発生したと見られるベンチマークジョブは 27572 ジョブ中 1546 ジョブを確認しています。
そして、ポータルとの通信でエラーが発生した時、数回に渡ってリトライするようになっていましたが、不具合が発生する時は 1 度も成功することなくリトライ上限に達していました。
当該ジョブについては、競技時間中の対応として選手側で追加の enqueue を可能にするため、運営側で CANCELLED あるいは ERRORED のステータスにバッチあるいは手動で変更していました。この影響があったジョブとして 27572 ジョブ中 1808 ジョブを確認しています。なお、アドホックな対応だったため、時間帯によってキャンセル基準が不揃いとなっていました。
本選では予期せぬ不具合があった場合でも自動でベンチマークジョブを完了させられるよう、supervisor でエラーが発生した場合は supervisor がエラーで終了するように変更、また supervisor 起動時に当該 supervisor が取得していたジョブを全てエラー状態へ変更するロジックを導入しました。なお、本選においては、本選中に実施した不具合修正のためのデプロイで発生した supervisor のエラーを当該ロジックでキャッチすることができていました。
予選ベンチマーカーから supervisor へ送信するメッセージの stdout/stderr フィールドを送信しない (supervisor 設計の意図通りにする) https://github.com/isucon/isucon10-qualify/pull/170/commits/2eb24446e0538a9e212ebde3c1f30adeb88ee9c5 supervisor がベンチマーカーを起動する際、
前述までの通り、競技時間中に複数のトラブルが起きていた事や、ベンチマーカーサーバーのオペレーションにおいて更なるトラブルを招いてしまった事から、ポータルチームの判断として、上記 workaround を競技時間中に実装することはせず、競技時間後、追試前に実装する事にしました。
また、予選結果における「ベンチマーカーの不具合による本選出場チーム」については、競技時間内に最後に正常に完了した負荷走行 (= ステータスが FINISHED であるジョブ) でスコアが 0 点と記録されているが、競技時間内の最後のジョブが ERRORED, もしくは CANCELLED となっている (= 正常に完了しなかった) チームについて、追試において記録されたスコアを検討しました。なお、「FINISHED であるが不具合で 0 点となってしまうケース」に関しては、判明している不具合や、競技時間内での対応では発生しません。
ベンチマーカーの不具合に際して、特に「スコアが出ない」「fail となってしまう」チームにとって原因特定が困難である、いわゆる「体験が悪い」状況を作ってしまったと理解しています。そして、これが予選競技の中で最も起こしてはならない類のトラブルに発展してしまった事について、運営チームは重く受け止めています。次回以降の ISUCON 運営チームに、トラブルの原因や反省点について引き継いでまいります。
この他にも、インフラチームのセキュリティ要件から SSH 公開鍵認証や SSH 踏み台が必要となっており、関連するサポート依頼に対し運営側の不備でないかの切り分けなどに運営チームのリソースが割かれていた事から、各種対応において不手際や遅延が目立つ状況になっていたと考えられます。
そして、イメージの完成遅延があり、テストを十分な時間、十分なメンバーで実施しませんでした。振り返りとして、完成途中のイメージを利用してでも、事前に全台展開のテストや、それを用いてのテストコンテストを運営で開催し、実際の最終形となったベンチマーカーを用いて予選問題に運営内の複数チームで取り組んでみる、といった試験のスケジュールを予め決めておき、実施するべきだったと考えています。開発環境で全てテストできる状態を出来るだけ早期に満たし、継続的にベンチマーカーを含め更新できるのが最善でした。
まず、参考移植やイメージ作成、展開作業、テストといった直前の作業について、予選競技日までに何が必要か、物理的なデッドラインというところを含め、スケジュールやマイルストーンについて運営チーム内でのコンセンサスが不足していました。ここから、展開作業などのバッファや、必要な期間の認識に作問チーム・インフラチームの間でズレが生じていたと考えられます。
そして、コミュニケーション面での問題について。はじめに、運営内でも複数の企業間で役割が分担されており、遠慮・プレッシャーを与えない配慮なども相俟ってチーム間のコミュニケーションが不足していた点も問題だったと言えるでしょう。それぞれに余裕がなくとも、チーム間で能動的に進捗確認や、最終的な試験を実施するデッドラインの定義、またそれを受けた代替案などを考える、といったことを遠慮せずに行うべきでした。
また、ポータルとベンチマーカーの通信部分に関しても、最低限のドキュメントやサンプルコードのみを渡し連携していましたが、わからないことがあれば質問がくるであろうという強い仮定で予選まで進行してしまいました。結果として、誤った利用方法から不具合に繋がりました。
最後にオペレーション上の問題について。予選ではおよそ 500 チームが参加、500 台のベンチマーカーサーバー、そして選手に提供する 1500 台のサーバーと規模の大きな競技環境を管理する必要がありました。
ベンチマーカーの無停止での入れ替え、万が一の時の非定型な一斉のオペレーションについて、十分に準備がされておらず、またそれを複数人が出来る状態ではありませんでした。そのため、競技時間内にできる対策が限られ、また更なる不具合の発生を防止するため、競技時間内に対策をしない判断が必要となってしまいました。
また、ISUCON10 アフターイベントを 10/13 (火) 19:00 よりオンラインで開催予定で、予選・本選作問チームおよびインフラチームが登壇いたします。本エントリで述べた点も含めて予選・本選を通して振り返りをしたいと考えてますので、是非リマインダー登録のほどお願いします。
運営チーム一同として、様々な要因から複合的なトラブルに発展させてしまったという認識です。これらの反省点を踏まえ、同種のトラブルを起こさぬよう、次の運営チームへ反省点やデータを引き継いでいきたいと考えています。その観点において、以下に 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 ポータルチームではリクエスト傾向や実際のベンチマークジョブのデータを保存し、次回以降の開催に活かせるようにします。
本選では予選で不要だと考えていたキャッシュの導入などを進め、同種の問題は起こりませんでした (そもそも予選に比べトラフィックが少ないという違いは存在します)。
ベンチマーク (負荷走行) における複数の問題について
最後に、競技時間中に発生していたベンチマーカーに存在する複数の不具合と、そこから派生したトラブルについて説明します。なお、競技中に 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 を実装して実施しています。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 よりオンラインで開催予定で、予選・本選作問チームおよびインフラチームが登壇いたします。本エントリで述べた点も含めて予選・本選を通して振り返りをしたいと考えてますので、是非リマインダー登録のほどお願いします。
