2018年09月18日

ISUCON 8 予選で惨敗しました(リュウグウ)


@methane です。とうとうISUCON予選敗退を経験してしまいました。 めちゃんこ悔しいです。

16:20には6万点台を出し、そこからはトップ争いを続けて17:47には10万点台を叩き出したものの、その後は2万点台しか出なくなり終了してしまいました。

それまでは調子の悪いときでも数回ベンチをしていれば少なくとも4万点台にはなっていたので、ずっと2万点台しか出なかったのは不運もあったのですが、そもそもスコアが安定しない原因を潰しておけば確実に予選突破できていたはずなのでこれも実力です。

やったこと

役割分担は、僕が全体を見る&アプリの実装もやる、 makki_d がアプリ、 mapk0y がインフラでした。選択言語はGoです。

最初の方はダッシュボードを作るのに必要な作業を2人にお願いしつつ、自分でもインフラ、アプリのコード両方を見て回りました。

ダッシュボードができてからは getEvent がネックなのが明らかになりました。一方レギュレーションでは予約とキャンセルのスコアが高く、ISUCON2との類似性からもその部分もキーになると判断しました。

getEvent も 予約もキャンセルも、全部 registration テーブルがキーになっています。とくに予約処理は見るからにまずいトランザクションになっているので、 registration テーブルのオンメモリ化に取り掛かりました。

といっても完全なオンメモリ化は諦めていて、ちゃんとDBに書き込んだ上で最新の情報をメモリ上にも載せておくだけです。また、メモリに乗せるのはキャンセルされていない予約だけです。

最初は予約処理とキャンセル処理でメモリ上のデータを正確に更新するところを作りきりました。これができたのがすでに15時ごろでした。(diff)

これができると、次は getEvent でループで registration テーブルを SELECT してるところをメモリ上のデータを使うように書き換えます。 (diff) これが 15:30 頃で、4万点台でやっとトップグループの仲間入りをし、ほっと一息。

次に、さっきの getEvent のループ内で RegisteredAt を求めるためだけに registration を配列から線形探索でやっていたのがネックになっていたので、ループの前に先に sheet id と registered at を対応付ける map を作って置くことで高速化 (16:10ごろ) (diff)

この時点で6万点台は出るようになっていたものの、スコアの乱高下に翻弄され始めます。インフラの設定変更を試してみても大幅にスコアが下がって、設定変更のせいなのかどうか分からなくて迷走してしまいます。 (TIMED_WAIT が多いから nginx -> Go を unix socket に切り替えたものの、スコアが上がらなくなって TCP に戻すなど)

17:00 を過ぎた当たりで、 makki_d が挑戦していたイベント全体のオンメモリ化のバグが取り切れなかったので、 getEvents で event テーブル全体を引いたあとに getEvent で event テーブルを1行ずつ引くという同じテーブルに対する N+1 を潰し (diff)、17:30 には7万7千点。

そこから再起動試験で一度失敗し、2度めの再起動試験で幻の10万点台を 17:47 に出します。

ここで止めておけば良いものの、この一度のハイスコアで「再起動したらスコアがよくなる、なんか遅くなるのは繰り返して実行してるからかもしれない」と誤認してしまいます。 このときに nginx のアクセスログが切れてなかったので、アクセスログを切ってもう一度やろうと指示を出し、結果競技終了までずっと2万点台、最後の1回は1万点台で終了しました。

敗因(技術的問題点)

終了後にメンバーと話し合って、多分これだという問題点を見つけました。

予約とキャンセル処理では、registration のオンメモリキャッシュの一貫性を保護する mutex の中でDBへの更新をしていました。それがつまり気味なのはなんとなく把握していましたが、原因や、ひどいときにどれくらい詰まるのかまでは把握してませんでした。

一方、DBの方でもなにかデッドロックのログが発生していることは気づいていたものの、 admin 系で複雑なクエリがあるので、 admin 系のAPI通しで競合する事があるのかなとあまり気にしていませんでした。

そして、その admin 系の複雑な長いSELECTクエリに、 "for update" が混ざっているものがあることも気づいていて無視していました。

これを総合して考えると、 admin 系の重い SELECT クエリが for update で registration テーブルを盛大に(全体を?)ロックし、予約か削除がロックを握ったままそれを待ち、 getEvent を利用しているすべてのAPIが引きずられて詰まりタイムアウトを発生させる、というシナリオに思い当たります。ベンチマーカーが公開されたら検証してみたいと思います。

実は、mapk0y が作業中に「MariaDBからMySQLに入れ替えます。」「トランザクション分離レベルを read committed から repeatable readに切り替えます」という報告はしてくれていました。SELECTクエリの中で for update が出てくるの、ダーティーリードを避けるためにロックを掛けていたとすれば、 repeatable read に切り替えたときに完全に不要になっていたはず…ぐぬぬ。

訂正: read committed になっていたのは mapk0y が MySQL に入れ替えるときに my.cnf に誤混入しただけで、初期実装は repeatable read だったようです。あのJOINを使ったずっと横スクロールしないと読めない長い一行SELECT文の中に無意味な for update が混じっていたのは、特に必要な理由がない純粋な罠だったのかもしれません。。。

反省点

最大の書換であるところの reservation オンメモリ化を自分でしてしまいましたが、これは makki_d に任せて、自分はもっと調査系に専念するべきでした。手を付けたときに makki_d が他の作業に取り掛かっていたのと、事前練習不足で makki_d が「オンメモリ化」をスラスラ書けるか解らなかったのと、何より「自分が何もできないまま敗北する恐怖」に負けてしまいました。

大きな改修+それを利用した大規模な高速化が終わってトップグループになったのが16時で、そこからは「競技終了までに何をするか/しないか」に頭が切り替わってしまったので、落ち着いて全体を注意深く調査することができませんでした。

他にも、次のような要因があったと思います。

  • 過去問では report 系APIは整合性検証のためだけに使われることが多かったのでほとんど見てなかった
  • 通過ラインがわからない恐怖から、遅くなる原因追求よりも調子のいいときのスコアアップを優先してしまった

本戦では1位を取るためにスコアアップ優先になるのはある程度しかたありませんが、予選ではトップスコアを取っても通過できなければ意味がありません。来年はもう少し落ち着いて、仕事で負荷対策の調査をするときのようにマズイ点を潰していきたいと思います。

感想

アプリのコードの規模、DBのスキーマの規模ともにISUCONに適したボリュームに抑えつつも、完全オンメモリ化(SELECTを削除し、DBへの書き込みをロック外に追い出しても整合性が担保できる)が難しい複雑なSQLが散りばめられているバランスが素晴らしかったです。いろんなチームがそれぞれの得意なやり方で勝ちを狙えたはずで、本戦にしないのがもったいない、これ以上ないくらいの良問でした。

また、去年の予選でやらかしてしまった原因の「予選で複数台構成」を今年も継承してきたことにも驚きました。参加者視点で見たら、万が一設定をミスってSSHできなくなるような事態になっても試合終了にならない安心感は良いですね。

その複数台構成の活用方法も、去年に比べてずっと自由度が高いのが良かったです。

本当にこれまでで最高のISUCONだったと思います。ありがとうございました。 これが予選なら本戦はどうなるのか、参加できないのが悔しくて仕方ありません。

songofacandy at 11:04│Comments(0)ISUCON 

この記事にコメントする

名前:
URL:
  情報を記憶: 評価: 顔   
 
 
 
Blog内検索
Archives
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。