Zenn
😺

ISUCON14に出場し161位も、環境チェックNGで失格になった話

2024/12/09に公開
ISUCON
isucon14
tech

まとめ

ISUCON4年目の出場にして初めての参加記です。

  • @itohdak
  • @Kotaro7750
  • @yakenji

の3人で参加しました。
Go言語で参戦し、結果は速報で10,883点で全体161位。
と思ったら、翌日正式結果を見ると環境チェックNGで失格になっていました。
過去一準備に時間を費やしただけに残念ですが、また来年も頑張ります。

やったこと

インスタンスのデプロイ

今年からpproteinを拝借しました。
これまでもAnsibleを使ってログを収集するなどある程度の効率化は入れていましたが、pproteinを入れて、集計情報がブラウザで直接閲覧できるようになり、ファイル管理とおさらばできたのは大変楽でした！
これまではあまり確認できていなかったpprofも簡単に見られるようになり問題箇所特定の効率も向上しました(が、今回のISUCON14ではアプリがCPUネックになるところまで到達せず、あまり火を吹かず)。

小ネタで、インスタンスデプロイにあたって、CloudFormation実行後5分経ってもインスタンスが立ち上がってこなくて不思議に思っていたら、AWSマネコンの右上に「バージニア北部」の文字が？！
前日も同じAWSアカウント(リージョンはもちろん東京)で練習していたのに当日になってなぜ。。焦りました。。

10:34 初期ベンチ 939点

Gitレポジトリへの資材の追加や各種ミドルのログの有効化のあと、初期ベンチを回しました。

11:13 インデックス付与 1,869点

インデックスがついていないスロークエリがありそうなので簡単なものから手をつけます。

https://github.com/itohdak/isucon14/pull/2
https://github.com/itohdak/isucon14/pull/3

横目で見える最も時間のかかっているバカデカクエリに警戒しながら。

12:36 chairの最新情報を管理するテーブルを新規作成 2,036点

横目で見ていたバカデカクエリに対処します。

SELECT id,
       owner_id,
       name,
       access_token,
       model,
       is_active,
       created_at,
       updated_at,
       IFNULL(total_distance, 0) AS total_distance,
       total_distance_updated_at
FROM chairs
       LEFT JOIN (SELECT chair_id,
                          SUM(IFNULL(distance, 0)) AS total_distance,
                          MAX(created_at)          AS total_distance_updated_at
                   FROM (SELECT chair_id,
                                created_at,
                                ABS(latitude - LAG(latitude) OVER (PARTITION BY chair_id ORDER BY created_at)) +
                                ABS(longitude - LAG(longitude) OVER (PARTITION BY chair_id ORDER BY created_at)) AS distance
                         FROM chair_locations) tmp
                   GROUP BY chair_id) distance_table ON distance_table.chair_id = chairs.id

Window関数（LAG）を使用した1クエリに3秒以上かかっているクエリで、小手先のインデックスだけでは効果がなさそうでした。
サンプルアプリの確認とコードリーディングの結果、

  • Ownerの持ち椅子の集計情報を取得するAPIで呼ばれていること
  • 最新の椅子の情報だけ管理できていれば十分であること

から、椅子の最新情報を管理するchair_total_distanceを作成しました。

  • テーブルスキーマの作成および初期データ対応 @Kotaro7750
  • アプリ側のクエリ追加・修正 @itohdak

で対応し、両者がかっちり噛んでベンチが正常に動いたときは感動しました。

https://github.com/itohdak/isucon14/pull/4
https://github.com/itohdak/isucon14/pull/5

ただし、このAPIは直接の加点要素ではないため、今思うとあまりスコアは増えていないですね。
ですが、バカデカクエリはいなくなりました。
DBの負荷を下げ、他のメインの処理にリソースを割けるようになったという意味でのスコアアップのように感じます。

12:53 追加のインデックス付与 3,833点

上述のバカデカクエリの負荷が下がったためか、他のスロークエリが見えてきたので、追加のインデックスを付与します。

https://github.com/itohdak/isucon14/pull/6
https://github.com/itohdak/isucon14/pull/7

DB分割を試みるも失敗 0点

このあたりで、DBのCPU負荷が下がり始め、DB:APPで7:3くらいのCPU負荷割合になりました。
CPU使用が競合している可能性を鑑み、DB分割を試みます。
手順はいつも行っているものなので、何も苦労することなくできたのですが、その状態でベンチを回してみると、クリティカルのエラーが出てFAILします。

time=13:07:07.715 level=WARN msg="椅子がライドを受理できませんでした (CODE=3): POST /api/chair/rides/{rideID}/statusへのリクエストに対して、期待されたHTTPステータスコードが確認できませんでした (expected:204, actual:400)"
time=13:07:07.745 level=ERROR msg=クリティカルエラーが発生しました error="椅子に想定していないライドの状態遷移の通知がありました (CODE=12): ride_id: 01JEJ766RPFR5K9AD2WFR16XQ6, expect: MATCHING, got: COMPLETED"

この理由は最後までわからず、最終的にもサーバは1台構成でした。

13:26 マッチングの頻度を増やす 4,237点

このアプリでは、乗客と椅子のマッチングは非同期で実施されるようになっており、このマッチング頻度は初期実装では500msに1回となっていました。
マッチング頻度を上げたほうが、送迎完了まで至れる乗客が自然と多くなるので、この頻度を上げます。
100msに1回、マッチング処理を回すようにしました。

https://github.com/itohdak/isucon14/pull/8

13:52 notificationのポーリング間隔を下げる 7,385点

nginxおよびmysqlのリクエストの内訳を見てみると、圧倒的にGET /notificationの頻度が多いことがわかります。
初期実装だとクライアントは30ms間隔で上記APIを呼んでくるので、一旦その頻度を下げます。

https://github.com/itohdak/isucon14/pull/10

あとから気付くことになりますが、このポーリング間隔を下げると、ステータスの更新遅れによりスコアが伸びなかったり、（実装によっては）クリティカルなエラーが出やすくなります。
実際自チームも最終的にはこの値をもとの30msに戻さざるを得ませんでした。

14:31 マッチングアルゴリズムの改修 8,469点

マッチング頻度と同じタイミングで、マッチングアルゴリズムにも目をつけます。
初期実装だと、ランダムな乗客をランダムな椅子とマッチングさせるアルゴリズムになっていたので、この改修を試みます。
@yakenjiが、Copilotを駆使し、Copilotに翻弄されながら、実装してくれました。

https://github.com/itohdak/isucon14/pull/9

よくわからないバグとの遭遇、そして、混沌へ。。。

上記まで完了したところで、一度mainブランチでベンチを回してみました。
すると、思わぬクリティカルエラーによりベンチが落ち始めます。
（マッチングアルゴリズムの改修と、notificationのポーリング間隔の変更がブランチが別れており、mainにマージされて初めてこの問題に遭遇した模様）

time=14:48:00.024 level=ERROR msg=クリティカルエラーが発生しました error="椅子がライドの完了通知を受け取る前に、別の新しいライドの通知を受け取りました (CODE=15): chair_id: 01JEJCYJTGPYQR7ACQGZ12HRD9, current_ride_id: 01JEJCYKYBKY21X4GWCCGGVZVX, got: 01JEJCYW71TRD7YN72GSS61AEX"

それに翻弄され、右往左往。
前述のnotificationのポーリング間隔も初期の30msに戻しました。

上記のバグは以降も亡霊のようにつきまとわれます。
その後、主に以下の観点について改修を試みたものの、最後まで完走することなく最後の3時間は水泡と帰します。

  • notificationのSSE化 @Kotaro7750
    • 自チームも多分に漏れずSSE化に特攻しますが、「なんの成果も得られませんでした！」
  • ride_statusesのトランザクション化 @itohdak
    • 上記エラーに対して、トランザクション処理がうまくできていないのが問題なのではと仮説を立てました。ride_statusの主キーはidとなっており、ride_idに対してはユニークではないために問題が起こっているのではないか、と。この仮説は蓋を開けてみると誤っていることがわかり（かつ、ride_idに対して複数のステータスを持てないと、現状のポーリング式のnotificationだと、通知ステータスをスキップしてしまい機能要件が満たせなくなる可能性が高い）、実装は期間内になんとか完了したものの、結局上記のエラーは解消されませんでした。。
  • マッチングアルゴリズムの改善 @yakenji

17:55 ログの無効化と再起動試験 10,229点

最後30分まで粘りましたが、にっちもさっちも行かず、最後にベンチが通った断面でログの無効化や監視用スタックの停止を行い、再起動試験を実施しました。
点数は少し伸びて1万点の大台に。

そして絶望の環境チェックNG NaN点

当日は21時前に各チームの結果速報が公開されて、自チームは冒頭に述べた10,883点で全体161位でした。
しかし、翌日公開された正式結果では、環境チェックNGによる失格。。。
泣きっ面に蜂、弱り目に祟り目、踏んだり蹴ったりな結果となりました。ぴえん。

途中から侵されたバグについて

コンテスト中に見舞われたクリティカルエラーは主に以下の2つです。
まだデバッグ中なので、検証し次第更新しようと思います。
（もう少し考えてみたいので、もし分かってもネタバレしないでね）

1つ目は、DB分割したときに初めて遭遇したエラーです。

椅子に想定していないライドの状態遷移の通知がありました (CODE=12): ride_id: 01JEJ766RPFR5K9AD2WFR16XQ6, expect: MATCHING, got: COMPLETED

これはローカルで動いていたisuride-matcher.serviceを疑っています。

2つ目は、notification間隔増大＋マッチングアルゴリズム改修を実施したあとに初めて遭遇したエラーです。

椅子がライドの完了通知を受け取る前に、別の新しいライドの通知を受け取りました (CODE=15): chair_id: 01JEJCYJTGPYQR7ACQGZ12HRD9, current_ride_id: 01JEJCYKYBKY21X4GWCCGGVZVX, got: 01JEJCYW71TRD7YN72GSS61AEX

これはマッチングアルゴリズムを疑っています。

原因が判明しました！（12/11更新）

上記のエラーはどちらも「マッチングにおいてトランザクション処理が担保されていないこと」、および、それにより想定外のマッチング処理の使われ方をすると「ライドのマッチングの組み換えが発生しうること」が原因でした。
上記の被疑はどちらも遠くはありませんでしたが、正しくは「ローカルで動いているisuride-matcherもマッチングアルゴリズム（とその実行間隔）も同じ問題に寄与しており、エラーの内容はその時々のタイミングによって複数パターン考えられる」でした。

想定外のマッチング

想定外のマッチング処理の使われ方というのは、「2つ以上のマッチング処理が同時並行で実行される」状況が起こる使われ方です。
それには大きく2パターンありました。

  • それぞれのインスタンスで動いているisuride-matcherが同じタイミングで実行され、影響を及ぼし合うパターン
  • 1回のマッチング処理にかかる時間がマッチングの実行間隔より長く、（同じインスタンス上で）マッチング処理が2つ以上同時実行されてしまうパターン

発生しうるエラー

では、「ライドのマッチングの組み換えが発生」すると、どのようなエラーにつながるのか。
それも大きく2パターンあります。
すでにマッチングされた乗客と椅子のペアのうち、

  • 椅子に、異なる新たな乗客が上書きで割り当てられてしまうパターン
  • 乗客に、異なる新たな椅子が上書きで割り当てられてしまうパターン

1つ目のパターンが発生すると、以下のエラーが出ることは想像に固くありません。

椅子がライドの完了通知を受け取る前に、別の新しいライドの通知を受け取りました (CODE=15): chair_id: 01JEJCYJTGPYQR7ACQGZ12HRD9, current_ride_id: 01JEJCYKYBKY21X4GWCCGGVZVX, got: 01JEJCYW71TRD7YN72GSS61AEX

2つ目のパターンが発生すると、実は以下のエラーが出ます。

椅子に想定していないライドの状態遷移の通知がありました (CODE=12): ride_id: 01JEJ766RPFR5K9AD2WFR16XQ6, expect: MATCHING, got: COMPLETED

こちらは少し解釈が難しいのですが、chairGetNotificationにおいて、椅子の最新ライドを取得する際にridesテーブルを参照していることがこの原因です。
マッチング処理の中でridesが上述のような想定外の上書きをされてしまうと、その椅子の最新ライドが（存在する場合）その直前に完了したライドと認識され、それはもちろんCOMPLETEDの状態なので、このような不可解な状況が生まれるのです（当日、私はride_statusesのトランザクション化がなされていないために、ステータスが何故かMATCHINGやENROUTEからCOMPLETEDに「進んでしまっている」と勘違いしていましたが、実は「戻っていた」のです）。

解決策

この問題を解決するためには、想定外のマッチングがされないようにすればよいです。

1つ目のisuride-matcherに対しては、

  • DB分割をする際に、ローカルで動いているサービスを停止し、いずれか1つのインスタンスだけで稼働している状態にする

などが解決策として考えられます。

2つ目のマッチング処理とマッチング間隔に対しては、

  • マッチング間隔を伸ばし、マッチング処理が2つ以上同時実行されないようにする
  • マッチング処理をトランザクション化し、仮にマッチング処理が2つ以上同時実行されてしまっても不整合が起こらないようにする

などが考えられるでしょう。

環境チェックNGについて

翌日失格を知ってから、当日マニュアルを見返しenvcheckの存在を知りました（おい）。
CloudFormationを回し、当日と同じ構成を作成し、envcheckを回したところ、以下のエラーが検出されました。

isucon@ip-192-168-0-11:~$ sudo /opt/isucon-env-checker/envcheck 
環境をチェックしています...
2個の問題があります
4個の EC2 インスタンスが検出されました (3個である必要があります)
vol-00661ae65b268c0cf のサイズが 40 GB です (20 GB である必要があります)

pproteinサーバを、競技用サーバと同じVPC内の同じサブネットに立てていましたが、どうやらそれがいけなかったようです。
次回からは、競技終了前にpproteinサーバを落とすことを胸に誓いました（今年もログによると18:18に落としていましたが、手遅れだったようです）。

Discussion