2018-09-17

ISUCON2018予選敗戦記

isucon2018予選、一日目にガラスボッチとして参加して見事惨敗しました。大会の感想と来年に向けての準備について書いていきたいと思います。
懺悔の用意はできてるか

事前準備

もともとはボッチ参戦予定でしたが、なんだかんだでなり（@iwa_tatsu）くんと一緒に出場しました。ガラスボッチだがボッチではない。
僕自身は初参加で、なりは去年のISUCONにも出ていたので、去年の問題とそのときにやったこと、上位陣のブログ記事などを参考に勉強会をやって役に立ちそうなことはprivate wikiにまとめておくなどしておきました。

去年のエントリまとめ

去年の予選は複数台構成で、3台のマシンにどうロードバランシングしていくのかが1つのキーだったらしいので、今年も複数台構成であろうということで、そのへんを意識しながら資料を漁っていました。
今年の環境はsshでCentOSの環境にアクセスしてやるということは事前に公開されていたので、僕の方でansibleを使ってgitやvimなどの基本的なソフトウェアは開始と同時に勝手に入るように用意しておきました。

言語選択についてですが、おそらくgo言語が実装が公開されている中では高速で有利であろうとは思ったのですが、去年はそうでもなかったらしく、
また、二人ともgoについての知識はなかったのでnodejsで勝負することにしました。
あと、僕の個人的趣味でScalaが好きだったので、スキがあればPlayに移植する計画も立てていました。
sbtが起動するために必要なものはansibleで入るように準備しておきました。

当日

mixiさんが会場提供してくれるとのことだったので、それに参加させていただきました。

問題開始と同時にsshキーの登録、ansibleをつかってのツールインストールはすんなりできました。
今回サーバーは3台与えられていて、初期状態でアプリケーションとDBが1台のみで稼働し、残りは何もしていない状態でした。
スコアはそのうち1台を対象に大量のリクエストを飛ばすので、整合性を保ちつつたくさんリクエストを返せばよい、という内容でした。

ウェブアプリケーションの構成を把握しようとしたが、どうもnginxの設定が見当たらない…と思ったら今年はなんとh2oという全く別のアプリケーションで動いていました。
DBもMySQLではなくMariaDBでしたが、これは想定の範囲内（多少設定に躓いた部分もありますが多分誤差程度）。

ログ解析

予定通りnodejsの実装に切り替えた後、ベンチマークを走らせました。初期状態ではせいぜい1000くらいのスコアしかでません。
では、ボトルネックはどこかな…とログ解析を開始しようとしたのですが、まずSQLのスロークエリが全くない。
あせりましたが、どうやら今年は一つ一つのクエリはそんなに重くないようです。
では、どのエンドポイントが重いのか。alpというのツールで一気にやってしまおう、と計画していたのですが、これを使うにはログのフォーマットをツールの期待する形に整形する必要があります。
nginxで予想していたため、h2oで同じようなconfigを書くかnginxに切り替えるかしかありません。

nginx用の資料はいろいろ集めていたため、はじめはnginxに切り替えようとしたのですが、csvファイルを出力するエンドポイントにて何故かレスポンスが途中までしか出ないという問題が発生したため、最終的にh2oでがんばることに。
格闘の末、ようやくalpが使い物になる状態に。
わかったことは

トップページへのアクセスがそれなりに多い上、一番時間を食う
/admin/api/reports/salesがアクセス回数が数回なのにめちゃくちゃ時間を食う
/api/users/:idもアクセスが多く時間がかかる

また、netdataをつかってのパフォーマンス監視もしていました。こちらはansibleで事前準備しておいたのでiptablesでポートを開けさえすればすぐに使えたのですが、
CPUがめっちゃ動いている、くらいの情報しかわからなく、実際にどこを改善させればいいのかを確定させるためにはalpのアクセスログが必要でした。

複数台構成

netdataの情報からCPUがかつかつでトラフィックも相当というのがわかったので、他のサーバーでもアプリケーションが稼働できるように設定しようとしました。
データベースは1台のみで動かし、残りはリモートからアクセス、という形に。初期化のときに使うコマンドと、アプリケーションが参照するDBの設定が分離されているのがちょっと罠ですが、割とすぐに稼働できるようなりました。
しかし、ベンチマークを走らせるとfailしてしまい、メッセージを見るとタイムアウトとなっている。
どうやら、大量のDBリクエストがあるため、リモートにDBがある状態だとそのオーバーヘッドでタイムアウトしているようでした。
そのため、単にロードバランスするだけではかえって遅くなる危険性があると思い、データベースのアクセスが少ないがCPUリソースを大量に消費する/admin/api/reports/salesのみ他のサーバーにプロキシすることに。
これはかなりきいて、いくつかのアプリケーションコードの改善と合わせてスコアは一気に10000点台に。

しかし、その後は後述するトラブルに見舞われ、思うように構成の見直しはできませんでした。

アプリケーションコード改善

トップページのアクセスから見ていったのですが、N+1問題のオンパレードという感じでした。しかし、いきなり全部変えるのは整合性を保つのが難しくなるので、細かい改善を積み重ねつつリファクタリングする、という感じにしました。
最終的にできたのは

getEvent関数中のreservationsテーブルのアクセスをsheet_idごとではなく一括で行う
sheetsテーブルは不変なので、初期化時にメモリに落としておく
ログインが必要とされるページの処理でnicknameを取得するために余計にDBを叩いていたのでcookieに保存
getEvent関数で取得されるreservationsテーブルの情報は/api/users/:idの表示に不要なので、専用関数をつくってに切り替えてそもそも叩かない
/admin/api/reports/salesはgzip圧縮して返す
くらいです。

とにかくDBへのアクセスを減らすことに注力しました。

謎のトラブル

10000点台を叩き出し、アプリケーションコードの改善を進めていたのですが、何故か良くなる変更のはずなのに10000点を大きく下回る、ということが連続してきました。
よくnetdataの画面を見ると、何もアクセスのないはずのサーバーのnetworkの使用率がやたら高いことに気が付きます。
実は複数台構成にしたり、手元環境からアクセスしやすいようにiptablesでかなり緩い設定をいろいろと仕込んでいました。これはまずいと思い、iptablesの設定を慌てて変更。これで多少スコアは持ち直したのですが、それでも低い。
どうも、このスコア、ブレブレなのは日常茶飯事らしいいので、これは仕方ないと思い、最後の調整を進めました。

ところが、終了30分前あたりから、なぜかベンチマークがfailになり続け全く通らなくなる、という事態に陷ってしまいました。iptablesの設定がおかしかったのか、と思いいろいろ再起動をかけましたが治らず。
アプリケーションコードを初期状態にするをしても治らず。/etc以下はetckeeperで管理していたのですが、それも正常だった頃と差分なし。
DBの内容を初期状態に戻すのも効果なし。そもそも今回は/initializeというエンドポイントを叩くとDBとが初期化されるようにデフォルトでなっていて、そこはかえていません。
結局この謎のトラブルを解決できないまま競技終了となってしまいました。
原因として考えられるとしたら

アプリケーションコードのバグ
- randomなケースも混ざっていたのだろうが、それでも10回くらい連続で落ちていたのはおかしい
- 初期実装にも戻したがfailした説明にはならない
h2oのバグを踏んでおかしな状態になっていた
- そういえばh2oの再起動を試していなかった
IPアドレスが変わるなどネットワーク環境がおかしくなっていた
- ベンチマークの実行はssh用のグローバルIPではなく、別の専用プライベートIPを利用していた
ベンチマークがバグっている
- これは他のチームでそういう報告がないのでほとんどありえない
永続化されていない初期設定が存在した
- 運営は再起動後、追試のためベンチマークを走らせるという作業をするため、これもなさそう

ベンチマークを走らせていると、全く同じアプリケーション・同じ構成なのになぜかfailするということが稀にありました。その時は単になんかネットワークの調子が悪かったのかな、程度に考えていたのですが、
もしかしたら何か関係があったのかもしれません。

結局、何が起きていたのかは特定できませんでしたが、このトラブルに遭遇してしまったとき終了間際ということもあり、パニックになってログを見返すなどのエラー特定作業ができませんでした。
仮に外部の影響だったとしてもそれを冷静に分析して、これは外部のせいであると断定するにいたれなかったのは問題でしょう。
いずれベンチマークコードも公開されると思うので、環境を再現して自分で追試してなにか原因をつかめれば、と思います。

Scala

実は/admin/api/reports/salesはScalaにすれば速くなるのでは、みたいな話はしていたのですが、さすがに余裕がありませんでした。
でも、勝ちを捨ててそういう方向性に走るのも悪くなかったかなあ

昼食

Uber Eatsで海鮮丼的なものを食べて優勝しよう（ここでいう優勝は競技での優勝ではない）という話になっていたのですが、そもそも店の選定をしていないという状態で、おまけに店を選定している最中にUber Eatsのサーバーが落ちるとかいうことに見舞われ、ろくな昼食が取れませんでした。
一応、SOYJOYを事前に買っていたのでそれでごまかしましたが、やはり海鮮丼には大きく劣り優勝には程遠い感じになってしまいました。

その代わり、夜は焼肉っしょ！！！ということで夜はいい感じの焼肉を食べたのですが、その焼肉屋に傘を置き忘れるとかいうトドメを刺されてとてもつらい

感想・懺悔

ベストスコアは13000くらいだったと思うのですが、1日目のトップチームが50000点台であったことを考えると、トラブル云々がなくても予選通過は無理があろう思われます。

問題について

非常に良い問題だったと思います。初期実装ではかなり改善するところが多い状態ですべてを解決するのは短時間では無理なので、ちゃんとボトルネックを見極め、改善する箇所の優先度を見極められる能力が求められたものだと思います。
やるべきことが多い分、3人目がほしかった。

あと、ベンチマークスコアのブレ幅は……去年も言われていたようですし、この手のコンテンストでは難しいのでしょうか

準備不足

ある程度の準備はしてきたつもりでしたが、ログ解析周りの準備はかなりずさんでした。alpの使い方も十分に把握できていなく、また、alpはかなりログの形を限定してくるため、
もっと軽量で使いやすい解析手段の用意も考えるべきでした。
細かいところで言うと、.bashrcや.vimrcなども多少はいじっておいたほうがよかったかもしれません。
普段であれば僕はdotfilesレポジトリに自分好みの設定を上げておきそれを入れているのですが、他の人も使うのに結構ゴテゴテしているので好みが分かれるかなと思って入れるのを見送りました。

また、firewallの設定方法も確認しておくべきでした。今回僕はiptablesでポート開放を行っていましたが、CentOSはfirewall-cmdで操作するのが普通です。いい加減なセキュリティ設定はやめるべきでした。
ここらへんは踏み台サーバー的なものを用意しして置くと更に楽できたかもしれません。そうすれば初めのssh-copy-idは1サーバーあたり1回ですみますし、ポートもsource IPで制限して開放すればリスクをかなり軽減できたと思います。

あと、keepalivedなんかも使えるかなあとか画策していたのですが、事前にまともに使う練習をしなかったので、結局使えず仕舞いでした。

ansibleはよかったです。ローカルのPCさえきちんと設定していれば動くし、単なるssh経由でshell scriptを走らせるラッパ程度の使い方でもかなり役に立つと思います。

整合性を保ちつつ改善する

今回の問題ではDBにアクセスする→結果を元にオブジェクトをつくる→足りない情報を別テーブルから複数のクエリを投げて取得するといういわゆるN+1問題が多く、仕込まれていました。
ただ、これを解決するにはコードが何をしているかをちゃんと把握して、書き換える必要があり、その際気をつけないと仕様を満たさなくなる恐れがあります。

今回、僕らのチームは変更したらいきなりベンチマークを走らせてそれでテストするというやり方をとっていて、非常にヒヤヒヤしながら開発していました。テストケースのようなものは特に与えられていなかったので。
できれば、自前の小さなテストケースを用意しておいて、それを変更ごとに走らせて整合性を確認する、とかができるとよかったかもしれません。
ただ、この短時間・少人数のコンテストでそれができるかはかなり疑問ではあります。

来年に向けて

そもそも来年開催されるかどうかは不明ですが…本当に面白いコンテストなので来年もあればぜひ参加したいですが、
運営はチーム数x3のサーバーを手配して参加費も取らないので相当大変だったと思います。本当にお疲れ様でした。

まず3人チームをつくる
今年の問題のトラブルの検証と延長戦
もっとansibleでいろいろ入るようにする
ログ解析手法の洗練化
firewall-cmdの勉強
昼食はちゃんと決める

己の不学を恥じる