ぽよメモ

レガシーシステム考古学専攻

壁を感じたISUCON12本戦

ISUCON Go

TL; DR

  • 実力不足を痛感した
  • なんとなく計測した気になってはいけない
  • 予め用意したものはとても役に立った
    • 更にブラッシュアップしていきたい

はじめに

この記事はチームツナ缶 としてISUCON12本戦の記録です。
予選同様、下記の様な分担で参加していました。

  • pudding（自分）：インフラ担当
  • taxio：アプリ担当
  • shanpu：アプリ担当

もし興味があれば、ぜひ予選のときの記事も読んでみてください。

poyo.hatenablog.jp

参加前の準備

ISUCON12予選ではデプロイの自動化などはうまく回っていましたが、反面計測周りに関しての体験が良くありませんでした。具体的には以下の様なフローになっていました。

  1. アプリやインフラへの変更をデプロイ（自動化されておりコマンド一つ)
  2. 全てのログをローテート（自動化されておりコマンド一つ）
  3. ベンチを回す
  4. 手元でpprofのコマンドを用意してポートフォワード越しに実行（もちろん実行者しか見れない）
  5. 終わったらサーバに入ってIssueに貼っておいた解析コマンドを実行してコピー
  6. まとめてIssueなりPRなりSlackで報告

問題は3つあります。

  • 手作業が多い
  • 実行者しかpprofの結果をみれない
  • 結果が一箇所にまとまっておらず、毎回どこにあるか探すことになる

これらを一挙に解決すべく、Ansibleでベンチ前後の処理を自動化しました。make bench すると以下の様な処理を実行するようになっています。

  1. スロークエリログを有効化
  2. 全てのログをローテート
  3. ユーザのインタラクションを待つ（ベンチリクエスト待ち）
  4. Enterが押されたらアプリケーションホスト上でpprofでプロファイリング
  5. ユーザのインタラクションを待つ（ベンチ終了まで待ち）
  6. Ansibleのinventoryに従いDBグループならpt-query-digestの結果を、nginxグループならalpの結果を取得し、レポートのMarkdownを生成しローカルにダウンロード
  7. pprofのダンプファイルをローカルにダウンロード
  8. ダウンロードしたレポートを一つのMarkdownにマージし、ローカルホストからghコマンドでIssueに投稿

これにより以下の様なレポートがIssueに投稿されます。本文が長すぎて投稿出来なかった場合でも、ローカルに同じ内容のMarkdownのファイルが残るのでそれを見ることが出来ます。

https://github.com/pddg/isu12f/issues/1#issuecomment-1229147907

レポートの例

結果としてベンチ前後の処理が大幅に楽になりました。
（pushしていなかったりしてcommitがない場合もあるので必ずでは有りませんが）現在のHEADを指すコミットハッシュをレポートに入れているのでどの時点の結果なのかよくわかるというのも良い点でした。 またpprofの実行結果を全ホストからダウンロードする方法も1コマンドで用意し、他のメンバーの実行したpprofでも簡単に見ることができるようになった点も大きかったです。

今回の出題内容

クッキーの代わりに椅子を生産するクッキークリッカーみたいなゲームに関する問題でした。

youtu.be

ユーザは椅子生産を効率化するアイテムでより大量の椅子を生産し、ログインボーナスを獲得してガチャを回してより強いアイテムを……みたいなサイクルを回すゲームになっていました。
アプリケーションの実態としては単なるWebアプリですが、フロントエンドのアプリケーションが運営が用意したCloudFrontから配信されていたのが少し驚かされる点でした。過去問再現が難しそう……

また、サーバが5台用意されていたところもこれまでとは違う点でした。幸いAnsibleではinventoryに2つホストを足すだけで良かったので、対応は難しくありませんでした。

やったこと

自分はインフラ担当なので主にその立場でやったことになります。

2022/8/28 20:14 追記
一時的にコードを非公開にしました。実行中のインスタンスが停止次第、再度公開する予定です。

github.com

10:00～11:00 初期セットアップ

nginx・MySQL・Go製のアプリケーションとほぼいつも通りの構成であり、迷うところはありませんでした。
alpやpt-query-digest、netdataなどを入れて、nginxやMySQLの設定をバックアップ、nginxのログをLTSVにしたりMySQLのbinlogを無効にしたりしていました。
あとはmitigations=offを入れたりしていました。ちなみに/proc/cpuinfoを見たらAMD EPYC 7763だったのでちょっとびっくりしました*1。

初期スコアは600くらいでした。

11:00～12:00 作戦会議とか

アプリの仕様の共有をして、取得されたalpの結果やスロークエリログからとりあえず方針を決めました。 まずサーバが5台あり、1人1台割り当てても2台余ることから、初手でDBを別ホストに分けました。 後はインデックス貼ったりN+1潰したりをやっていこうという方針で行きました。

このあたりは何かやるだけスコアが上がるのでとても楽しかったです。

12:00～13:00 obtainItemの闇に触れる

obtainItemという関数があるのですが、こいつはobtainという名前に反して内部では状態の更新をしており返り値はどこからも利用されていませんでした。
ヤバすぎる関数なのでなんとかしたかったのですが、これの調査をしているだけでかなり時間を持って行かれたのが痛かったです。同時期の他の変更とのコンフリクトを避けるため、ひとまず内部の処理を関数に分けるリファクタを加えました。

13:00～14:00 admin関連のテーブルを別DBに分離しようとしてベンチが落ちる

DBの負荷が相変わらずなので、一部のデータだけでも分離できないかと考え、ひとまず他から参照されて無さそうなadmin_usersとadmin_sessionsのみ別DBに分離しようとしました。
use isu4 as Admin DB host by pddg · Pull Request #19 · pddg/isu12f · GitHub

が、ベンチがコケるので諦めました。この時点で20000点くらいは出ておりこのままいければそれなりに順調だった（と思う）のですが、このあたりから何をしてもスコアが伸びなくなり、焦り始めます。

14:00～15:00 generateIDで重複する

単に現在の時間をナノ秒単位で返していただけの実装がduplicate entryと言われるようになってしまったので乱数に変えられないか調べていました。
ORDER BY id ASCしているテーブルは自分たちで採番していなかったので乱数でイケると判断してrand.Int63()に変えました。

このあたりでRedis欲しいかもと言われたので、余っていた4台目にRedisを入れ設定し、環境変数にホストやポートなどを入れました。
Introduce redis by pddg · Pull Request #24 · pddg/isu12f · GitHub

15:00～16:00 alpの結果がおかしい

行き詰まってきてしまい、色々見直そうということでプロファイリング結果を見ていたのですが、叩かれているはずのエンドポイントがalpで観測出来ていませんでした。
明らかに今回最大のミスで、alpのオプションを初期のログから目grepで組み立てて運用していたのが良くないポイントでした。

明らかにこれによって解像度は上がりました（が、結局スコアに繋がる改善ができず……）。

16:00～17:00 泥沼にはまる

スコアがこの時点で14時辺りから変わっておらず、打開策を見つけられなくなっていました。

17:00～18:00 とにかく再起動試験を通す

スコアは残したいので再起動周りに手を入れ始めました。 DBが起きてくるまでアプリ側は無限ループしたり、pprof切ってログ切ってnetdataをアンインストールして……みたいな感じで計測系をひたすら外していました。

再起動して何回かベンチ回してコケないことを確認して、最高スコアの22000あたり（うろ覚えだった）が出たところで終了にしました。

結果

各チームの最終スコア

チームツナ缶はスコアを残すことに成功し、最終スコアは21710点でした。得点のあるチームの中では上から15番目（精一杯好意的な解釈）でした*2。
失格するチームも多い中得点を残せたのは、flakyなfailを潰すために何度もベンチを回したり*3、丁寧に再起動周りをケアして、自分で再起動回してベンチがfailしないことを確認したおかげかなと思います。

振り返り

alpのオプションミス

明らかにこれは痛かったです。正規表現が間違っており、分離されるべきパスが全て集約されてしまったことで誤ったエンドポイントが遅いように見えていました。
アプリを見る前にログを目grepしてオプションを組み立てていたのですが、アプリのコードがそこにあるのだからそれを見て組み立てるべきでした。

シャーディングの観点の欠如

今回はユーザ同士のインタラクションがなく、完全にそれぞれ独立しているためシャーディングをすれば余っているサーバを活用できました*4。IDの採番のロジックも握っているのでどうにでもなったはずです。
が、そもそもこの発想に至っていませんでした。予選がSQLiteで複数サーバにシャーディングできなくて困った～～って話をやったばかりなのに、一体何を学んでいたんでしょうか……？

アプリケーションログの軽視

あまり良い手立てを思い浮かんでいなかったのでアプリのログは愚直にjournalctlで見ていました。
が、他のメンバーはあまり慣れておらず効率的なログの閲覧ができていませんでした。これによりデッドロックに気付くのが遅れたり、作業が遅くなったりしており、大いに改善の余地があります。

nonyleneくんがやっていたように、ログとトレーシングの基盤を用意するのがいいのかな……と考えていますが、来年の僕に期待します。 nonylene.hatenablog.jp

デッドロックの解消の知見が乏しい

/login という重いエンドポイントがありました。ここではログイン処理（パスワードチェックとかsession周りとか）に加えてログインボーナスの処理などをやっており、非常に複雑なエンドポイントになっていました。
alpで見ると全アクセス中このエンドポイントは500のケースがかなり多く、ベンチの結果にも出ていましたがそこまで気にしていませんでした。

が、実はデッドロックを引き起こしておりこれを解消しなければそもそも遊んでくれるユーザが入って来れないという状況になっていたようです。
終盤はtaxioがずっとこれを見ていてくれたのですが、何がデッドロックしているのか、どうすれば解消できるのかが掴めず最後までどうにもなりませんでした。ここがスコアを伸ばすポイントだったのに、みんな目先のN+1やスロークエリにとらわれてしまっていました。

また、自分がDBのデッドロックに詳しくなく、あまり手が出せなかったのも良くなかったです。とはいえギャップロックとかネクストキーロックくらいの知見はあるのだから、分離レベルをREAD COMMITTEDにしてみるとか*5それくらいは出せたはずでしたが、競技終了後に思い出しました。

来年に向けて

他のチームのスコアを見ると、自分たちのチームと見えている世界が違いすぎ、壁を感じました。ただし「また新しい知識を吸収して来年こそは本戦でも爪痕残すぞ」という気持ちになってきたのは良かったと思います。

幸い数日間、感想戦としてポータルやインスタンスを提供して頂けるとのことなので、冷静になった頭で色々ためしてみたいなと思います。

運営の皆さん、ありがとうございました！優勝のNaruseJunチームはおめでとうございます！
来年また対戦よろしくお願いします。

*1:勝手にXeonだと思っていました

*2:最下位だとLINEのまた会いま賞を受賞できたので惜しかったなとちょっと思ったのは秘密です

*3:合計121回回したらしい。全体で、上から4番目でした。これは明らかにベンチ周りに関して自分が手を入れた成果が出ていると感じました。

*4:ただし後述するデッドロックは解消できていなかった可能性が高く、これでもスコアは伸びなかったかもしれません

*5:これで解決する気はしませんが……