ISUCON 10 本戦に参加しました
ISUCON 10 の予選・本戦に「いすこんがさき、しゅうろんはあと」で @chigichan24 と @Pelkira と参加しました。結果は予選が総合 107 位 (学生枠 4 位で本戦出場)、本戦 18 位 (またあいま賞) でした。
スコアは予選が 1,301 点、本戦が 11,000 点ほどでした。 この記事では本戦問題の回答解説にあまり触れられていません。スコアが跳ねた回答を期待される方は他の方の記事や講評を参照してください。。
言語は今年から Golang に変更しました。我々のチームが本戦の時間内でやった内容は以下です
- 計測の効率化 (半自動化, 結果は自動的に Discord にポスト)
- AudienceService ListTeams の N+1 修正
- 不足した index の追加
- contestants.team_id
- teams.withdrawn, created_at DESC
- score_raw, score_deduction
- benchmark_jobs.team_id
- notifications.contestant_id, read
- TeamCapacity = 60
- 「あるべき通知を受信していないことが検知されました」の修正 (不発)
- makeLeaderboardPB のキャッシュ (不発)
また、我々のチームの予選時の内容は @chigichan24 の記事が本質情報なのでこちらを参照してください。 chigichan24.hatenablog.com
予選振り返り
学生枠突破勢なので、一般突破勢との差が練習量や経験以外に起因して何かあるはずです。本戦では枠に関係なく激突することになるので、戦略的な違いがあるなら研究する、基礎的なことが抜けていたなら改善することが重要そうです。てことで、期間は短いですがそれなりに振り返りをしました。チームの二人とも議論して課題を洗い出しました1。議論感謝します。
予選時の概要
予選で我々のチームが時間内に行ったことは以下です。
- 不足した index を追加
- 関数 searchEstateNazotte の N+1 修正
- Bot からのアクセスを弾く
- とりあえず複数台構成 (DB, App, App)
予選問題はアプリのコードがシンプルながら修正すべき箇所は多かったです。時間内で修正できた項目は半分くらいでした。 想定解答を見てもおおよそ半分くらいであることが分かります。
割当は以下のような感じ
Who | Role | |
---|---|---|
@Pelkira | タスク管理、Clar 報告 | |
@chigichan24 | 計測や改善 (DB/App/Infra)、DB 設定変更多め | |
@k5342 | 計測や改善 (DB/App/Infra)、計測多め |
振り返り
競技中は時間がとても早く感じます。8 時間があっという間に過ぎていくので競技中はなかなか認識できなかったのですが、後からログを見つつ振り返るとわかることもあります。 個人的にログを見て思った点としては、常になんか作業してた割には思ったよりスコアに影響する作業をしていなかった点2。例えば N+1 を潰したのは予選終了 1 時間前でした3。 N+1 を潰す行為自体はサクッできたので良かったのですが、そこに到達するまでが長かったです。 典型的な N+1 は ISUCON 的には早々に片付けるのが定石にもかかわらず、終盤に手を付けることになった点4は時間管理の点で再考の余地がありそうです。
課題: 時間管理
時間管理の文脈は競技時間全体の管理と各タスクの時間管理との二つがあります。
まずミクロな管理 (後者) としては、タスクにもよりますがひとつの操作は長くとも 30 分~ 1 時間程度で終える程度の速度で行われるべきです。バカデカタスクを一気に片付けようとするとバグって多くの時間を消費するので、小問題に区切って少しずつ改善する操作が肝要です。
つまりタスクを実行する場合は想定時間と想定リターンとのトレードオフをうまい具合に考えつつ、想定時間を超過した場合に軌道修正するか継続するかを考慮する必要があります。ここは Pelkira 先生が物凄く頼れるので予選に引き続き担当になります。が、予選と違って本戦はプリエンプションを強権的に行えるようにしました。なぜなら、わたしはひとたび作業に熱中すれば時間を忘れて目の前にある (技術的な) ロマンを追い求めてしまうからです5。
マクロ的な観点 (前者) では、直近の ISUCON 予選は二部構成である点に着目します。index を貼る、典型的な N+1 を潰すあたりの定石ができてスタートライン。で、その後はアプリの特性を考慮した最適化バトル開始と思っています。 個人的な考察ですが、予選の学生枠突破勢は定石を突破したチーム、一般枠突破勢は後半で最適な手を打てたチームだと思っています。本戦はその中で勝者を決める戦いになるので予選とは違うし、特に後半でいかにスコアを伸ばすかが重要になります。前半の定石部分をさっさと終えてしまって、後半に時間を残すこと、つまり、アイデアをひねり出す猶予を確保することが課題でした。そのためにも ISUCON の競技時間中の手戻りは避けたいです。
課題: 手戻りを防ぐための計測
手戻りをしないためには計測が不可欠です。というか、操作は全て計測によって根拠付けるべきだと思っています6。ここでいう「手戻り」は定石で行うべき典型的な最適化が漏れたまま後半にあたる作業を行うことです。後半ばアプリの内容を詳細に理解する必要があるので、手戻りが発生するとコンテストスイッチの切り替えコストがでかい印象。また index や N+1 は潰されたと仮定して最適化を考えることが多いのでハマりやすい印象7。
そういう背景で計測は大事なんですが、計測に関しては以下の二つの問題が依然としてありました。
手際
ISUCON は負荷走行時に発生するボトルネックの改善が重要なので、負荷走行時に残るログ (e.g. access.log, slow-query.log) が重要です。ログの中に残るノイズを減らすため、負荷走行前にログファイルを空にしておくといろいろハッピーなのですが、これにこだわりすぎて時間を多く消費した印象でした8。こういうテンプレ操作は自動化できればいいですね ... (1)計測をわかっとらん
直近でアプリネックな問題が続いていた関係もあり9、決め打ちでアプリだけをみていた。MySQL の slowquery なんかアウトオブ眼中やった。で、アプリも関数レベルでしか見てなかった。実際、予選問題は DB ネックだったのでボトルネックの把握は推測になってた。関数 searchEstatesNazotte が重いことは分かっていたのですが、本丸である N+1 を潰さずにインパクトの小さい early return をいれるなどしてました。本来、(システムのボトルネックを把握するための) 計測はトップダウンで行うべき。当たり前なんだけど競技中は様々な情報が飛び交うので目がいってしまう。予選中の操作では、計測→改善のイテレーション中ではない孤立した操作がいくつかあった ... (2)
本戦目標
以上のような問題を解消するために定めた目標が以下。どれも基礎的な部分で、頭では分かっていることだけど実行が難しい
(1) ボトルネック改善のイテレーションの高速化
これは計測回数を増やすことが重要です。計測はテンプレ操作が多いので自動化スクリプトをかけばよいでしょう。ということで自動化スクリプトを用意しました。本戦出場チームでも環境構築やプロファイラの導入、計測などのテンプレ操作は自動化しているチームがそこそこいた印象です。自動化できる部分は自動化して効率化することにしました(2) 根拠のある改善
ボトルネックをトップダウンで絞り込むことにしました。また、計測→改善のイテレーションの完成を重要視することにしました。作業者は常に作業内容と根拠を語れることを意識することにしました。
チームとしてはタスク単位で役割を厳密に定めること (作業者間の同期を減らす)、時間管理の優先度を高めることなども再度確認しました。その上で個人的な課題も洗い出して本戦に臨むことにしました。
本戦
役割分担は以下のような感じに
Who | Role | |
---|---|---|
@Pelkira | タスク管理、Clar 報告、時間管理、怪しいコードを報告 | |
@chigichan24 | 計測や改善 (DB/App/Infra)、DB 設定変更 | |
@k5342 | 計測や改善 (DB/App/Infra)、Nginx 系 |
本戦問題
本戦は未来の ISUCON の進化形、エクストリームなコンテストである EXUCON のポータルサイトがメチャクチャ重いのでなんとかする、というものでした。本戦は毎年お題が動画で公開されます。今年は YouTube でも見れます。以下の動画です10。 www.youtube.com
なお HTTP サーバは Envoy でした。本戦で出そうだなと思ってたけど、本当に来るとは。Nginx お世話係は失職しました。Nginx を前段に置いても良かったのかなあ
序盤
12 時くらいまでは当日マニュアルとか環境チェックとかいろいろやってた。概要としては以下のような感じ
- 環境構築 (自動化スクリプト修正、slowquery 有効化、pprof)
- 初期ベンチ
- 環境のチェック
- server1 は CPU 2 cores, RAM 1 GiB、portal を置けば良さそう?
- server2 は CPU 2 cores, RAM 2 GiB、DB を置けば良さそう?
- server3 は CPU 4 cores, RAM 1 GiB、benchmarker を置けば良さそう?
- バカデカ・クエリの存在に気づく
- index を追加してみる
初期スコア 6,000 点くらい
ここはトップダウンに計測した結果、DB の CPU が 100% で張り付いていたので DB バウンドと判断した。slowquery を眺めるとバカデカ・クエリがあるのを発見。だけどコイツが本当に重いかどうか分からんかったのでインデックスか適切に使われているかどうかを EXPLAIN で見て判断することにした。
また環境が珍しくヘテロな構成だったので、複数台構成も機能ごとの特性を考慮して分離したいなっつった。が、機能ごとに適切なノードを選択するにはある程度チューニングしないと特性が見えないので、複数台構成は後回し。最初は DB の CPU 負荷を下げることにした。
13 時ごろ
- index 不足に気づいたので追加する。schema.sql の修正 ... ※
- 参加者数を増やしてみる
スコア 10,000 点くらい
で、index 効いたじゃ~んとか言う
ここはバカデカ・クエリがボトルネックだと思ったので、バカデカ・クエリが index をきちんと使っているか確認した。具体的にはサブクエリで発行する SQL 文の index が適切に貼られていなかったので追加した。同時に問題サイズ (TeamCapacity) を大きくしてみて、現状のアプリでどれだけ耐えれるかを検証していた。それらの変更が同時に master に入ってスコアは 10,000 点ほどに到達。
直後の結果で slowquery の上位が SELECT 1 FROM benchmark_jobs WHRE ... FOR UPDATE
になったのでボトルネックが遷移した、と感じた。
slowquery は次点で INSERT INTO notifications
が来た。ここは INSERT なので DB のライトバッファを増やせばとりあえずなんとかなるかなーとか考えた。だけどメモリサイズが小さいので DB 移設後に行うことに。
さらに下には N+1 が生えていた。ここは Pelkira が N+1 に含まれるクエリで仮想参加者が増えると効いてきそうだと報告してくれたので修正することにした。
14 時ごろ
- スロークエリ眺める。
SELECT 1 FROM benchmark_jobs WHRE ... FOR UPDATE
と向き合う - バカデカ・クエリ実行における index 不足に気づいたので schema.sql を修正して ADD INDEX ... ※
- chigichan24 がシュッと ListTeams の N+1 を修正。神
スコア 11,000 点くらい
SELECT 1 FROM benchmark_jobs WHRE ... FOR UPDATE
の件は benchmark_jobs が行ロックなのと、処理内容としても仮想ベンチマークサーバがエンキューを待っているだけなので slowquery で上位に来るのは当たり前で修正しなくても良さそうと判断した。とはいえ、コードで Sleep していたのでこの間隔を調整したらスコアが上がるか、トランザクション外せないかを試した。トランザクション解除はベンチがコケてダメだった
slowquery は依然として INSERT INTO
が上位だった。これは Write だし DB のバッファキャッシュを増やす運用かなあとか言った。
15 時ごろ
- ※ の index が本番 DB に反映されてないことが発覚
- k5342 がミスって DB を破壊
- k5342 が頑張って DB を復旧
- index を反映
スコア 12,000 点くらい。Huh ???
追加で貼った index はさほど意味がなかったのかもしれない
slowquery は依然として INSERT INTO だった。このあたりから notification 関係の減点や fail が目立つようになる。妙だな
16 時ごろ
- 問題サイズが大きいから fail するのでは?となったので問題サイズを下げてみると pass するように。すると slowquery のトップにバカデカ・クエリが返り咲いた
- DB を server2 に移動
- メモリが大きいのでキャッシュが効くだろう
- chigichan24 が DB のキャッシュサイズを引き上げる
17 時ごろ
なんだかんだあって残り 1h ほどになった。この時点で抱えていた大きめの問題は二つ。
打倒・バカデカ・クエリ
紆余曲折ございましたが。結局、この時点までで最も重いクエリは依然としてバカデカ・クエリだった。DB バウンドなのも変わりなし。妙だな。単純にクエリが重いのか?ここでようやくキャッシュの話題を思い出す。マニュアルには Audience は仮想リーダーボードが 1s 古くても許容しますと書かれていた。
キャッシュの実装は二択ある。Audience 用に時間でキャッシュするか、Audience/Contestant 用に benchmark_jobs テーブルの最終更新を見てキャッシュするかの二択。が、前者の時間基準では Contestant 側の負荷低減にはならないこと、時計のずれやわずかな遅延によって fail することが容易に想像できたので、後者の厳密なキャッシュを実装したかった。いずれにしても 30 分ほどあればできそうと見積もる。ランダム fail 問題
問題はバカデカ・クエリだけではなかった。ランダムで fail する notification 問題もある。残り時間は 1 時間ちょっと。イマイチ原因がぱっとしないクリティカルな問題を残り時間が少ない状態で二つも抱えることになった。
・・・残り 1h といえば、再起動試験は丁寧に 1h ほど掛けるというのがチームで決めた内容だった。目の前には二つの重めの問題。ついでにノードも三台全部使い切っていない。もう問題は山積みである。どうするか?と一度全員の作業を中断して議論することにした。
この時点でのスコアは best: 12,000 で latest: 11,000 ほど。他のチームは fail が多めで latest: 0 のチームが多かったが best は 20,000 ほどに到達していた。大胆な変更なしには到底追いつけないだろう。ISUCON のスコアは best で決まるのではなく、最後の負荷走行結果である latest で決まる。我々のチームは fail していないのでスコアランキングでは上位だったが他のチームの best で考慮すると下位の方だった。
ここで、取りうる選択肢は以下
- DB をコア数が多い server3 に移譲する
- benchmarker を server3 に切り出す
- ランダム fail 問題に取り組む
- キャッシュを実装する
- 再起動試験をする
議論では DB の server3 移管はメモリ量が少なくなる点がマイナスに作用しそうだったのでパスすることになった。また benchmarker の移管は Envoy に不慣れで時間の見積もりができない点からパスになった。 残る選択肢としては三種類で、作業を投げて再起動試験で fail しないことを保証する、ランダム fail 問題を全員で眺めて安全策を取る11、ランダム fail とキャッシュを全部やる冒険に出るかの三択。ここで、スコアが伸び悩んでいること、このまま fail してもしなくても順位が芳しくないことを考慮し、冒険に出たい、全部やろうと k5342 が我儘を言った。二人とも乗ってくれた。申し訳ないです。ありがとう。キャッシュ実装はゴールが見えていたので k5342 が担当し、fail の原因調査を chigichan24, Pelkira が取り組むことになった。
終盤
終盤は以上のような経緯もあり、本当に心臓に悪かった。心拍計を見ると 130 BPM とかのタイミングがあった。
- バカデカ・クエリのキャッシュを試みる (16:40)
- ランダム fail の原因は特定しきれなかった
キャッシュの実装は動作はした。が、更新のタイミングがどうもおかしい様子だった。負荷走行後の最終チェックでコケたりコケなかったりしたので revert になった。 ランダム fail の問題は特定できなかった。
結果としては残念ながら両方ともに間に合わなかったが、残り 15 分になったので強制的に切り上げて再起動試験に回した。
- 再起動テスト (17:45)
- 問題サイズ変更 (17:56)
- fail する可能性があったので問題サイズを下げた
- VSCode がリソースを食いつぶしていた?ので退場後、計測
残り 5 分でパラメータ調整 (参加登録チーム数) をしてました。パラメータ調整は本番環境で本番コードを直接編集する形で行ったので、fail しないかめっちゃ緊張しました。緊張で張り詰めた空気の中、@Pelkira と @chigichan24 とで操作ミスがないようメンタル的な支えをしながら作業しました。
最終スコアは 11,077 点でした。ベンチは pass した。よかった。
間に合わなかった
本戦の中で間に合わなかった点は以下です。残念
- notification バグ修正
- バカデカ・クエリのキャッシュ
- 随所の N+1 修正
- 三台使い切る
学び
ORDER BY DESC
では降順インデックスが効かない点 (MySQL < 8.0)- SPATIAL INDEX
- MySQL 8 では GRANT ALL でユーザを作ってくれない件
- Envoy Proxy、、、本当に来るとは
- AppArmor との戦い
- VSCode によるサーバ破壊 (メモリ 1 GiB なので)
- Makefile 便利
- 問題サイズは下げた状態で改善プロセスを回しましょう
- index を貼った直後は指差し確認をしましょう。これ大事。ヨシ!
後日談
キャッシュのソースコードはここにあります。これ、、、は、バカデカ・クエリを実行したときに得られるリーダーボードのデータ構造を、その時点の benchmark_jobs.id の最大値でもって保持するキャッシュです。で、バカデカ・クエリを実行する前に benchmark_jobs.id の値を DB に問い合わせて、知ってる値でなければリーダーボードが更新されたとみなしてバカデカ・クエリを発行する。
これ、、、キャッシュの invalidate の条件を思い切り間違えてました。リーダーボードの更新タイミングはエンキュー (INSERT INTO benchmark_jobs
) したりベンチマーク結果が出たとき (UPDATE benchmark_jobs
) ですから、benchmark_jobs.id の最大値を見るだけじゃだめですね。。。CHECKSUM TABLE
あたりを見るのが良いのでは、とか思っています。本戦インスタンスは暫く残していただけるようなので、試してみます。
振り返り
タスクごとの細かい時間管理は作戦はめちゃくちゃよかった。プリエンプションもうまく動いた。一方で全体の時間管理がズレた点は得るべき情報をきちんと吸い上げられなかった点で無念。。。特にindex への執着とか。。。index が貼られたかどうかチェックを忘れていたことと、index を貼れば速くなるやろって期待、キャッシュを思いつくまでに時間がかかりすぎた点があんまり良くなかったかな。
計測は自動化の効果がかなりあって、全員が気軽に計測・閲覧できる環境を実現できました。自動化は偉大。 結果の解釈はもう少し原因を分析できるようになりたいですね。途中でベンチマーク内容に複数の変更が混ざってスコアが跳ねたので錯覚してしまった。あとは後半のアドホックな最適化フェースでは素早く最適な手を選択できるようになりたいですね。ここはヒントや突破口という意味でも当日マニュアルめっちゃ大事だなあと、改めて思いました。
さいごに
ISUCON ですが、こんな超絶楽しい問題と超厳密なベンチマークコードが毎年オープンになること、そもそも大会が毎年開催されていること、また無料で参加できること、これら全て貴重な機会をいただけることに感謝いたします。 運営のみなさまを始め、ISUCON にご尽力いただいた全てのみなさまに感謝いたします。ありがとうございました。
また本戦の賞として、「またあいま賞」を拝受しました。 私は学生枠として参加できるのは今年で最後です。来年12は一般枠で予選突破できるように精進してまいります。また本戦でお会いしましょう!修論もがんばります。
ISUCON、期間を長く一ヶ月開催とかどうでしょう。C++ でフルスクラッチ実装するチームが登場したり CPU キャッシュレベルまでカリカリにチューニングしたりするエクストリームチューニングコンテストになったりするんですかね?見たくないですか?これは軽率な妄言で SRE 的なとか問題が様々あるのは承知しております。すみません
-
計測しながらコード読みつつ kataribe の config を書きつつ issue を整理しつつ議論しながらベンチマークの進行状況を凝視する、とか。めちゃくちゃ計測にリソースを割いていた↩
-
定石とか言ってますけど計測は大事です!!!!↩
-
たとえば超絶複雑 N+1 解消のために超絶複雑バカデカ・クエリをハチャメチャに JOIN して摩訶不思議・アルティメット・スーパー・バカデカ・クエリに仕立てるなど。動くけど作業時間かかりがち。スコア的にもブレイクスルーになることは稀な印象↩
-
計測結果を咀嚼して取りうる選択肢の中から適切な手札を選択する操作が難しい点もあるが、それは別の話↩
-
index や N+1 はボトルネックになることが多い印象。これらは計測結果から意識的にコードを確認したり SQL を EXPLAIN しないと気づけない↩
-
rm access.log 後 restart nginx を忘れてログが無いとか。truncate って打つのは長いからね (?)↩
-
例えば ISUCON 9 予選の bcrypt 問題が記憶に新しい http://isucon.net/archives/53789931.html↩
-
本戦問題紹介のシーンで仮想世界の miraXi さんがスマホの時刻を確認したとき (動画 2:30 あたり)、ちょうど現実世界の時計と同じ 9 時 54 分を表示していて、ライブにもかかわらず芸が細かくて開幕早々涙が止まりませんでした↩
-
ISUCON 11 楽しみにしてます!!! https://twitter.com/941/status/1306898707879587841↩