ISUCON8で準優勝した - math314のブログ

大体はchibieggが書いてくれているので落ち穂拾いです ISUCON8で準優勝しました « chibiegg日誌

ISUCON8の決勝で準優勝しました、優勝できず非常に悔しかったです。競技終了直前では50,000点を超えていたものの、再起動後のチェックで31,000点程度と大幅に下げてしまいました。

メンバーと担当は予選と変わらず

chibiegg: インフラとコード
misodengaku: インフラとコード、エスパー
__math: コード

本戦のrepoはこちら、コミットログは例の如く雑です、8時間しか使われないので… github.com

時系列順

10:00

chibieggがansibleを書いている、sshの設定とかをしているようだが問題が公開されたので見る。

マニュアルが結構長い。misodengakuと同時に読み始めて、マニュアルを読み次第goのコードを読み始める。

SNSで拡散という項目をマニュアルでもコードでも見つけるが忘れる。

11:00 まで

とりあえずベンチマークを走らせてもらう、500点前後？

MySQLのslow logとnginxのアクセスログを出してもらう。

/info, /orders へのアクセスが大半の様子。

CPUは200%ガッツリ使っている。

帯域を頑張る問題には見えない。

流石に本戦でオンメモリ戦略をやるのはしんどいだろうということでMySQLは引き続き使うことにする。

DBとアプリケーションサーバを分離してもらう (misodengaku, chibiegg)

そうしている間にあからさまにLIMIT 1が必要なコードを見つけたのでつける。

ベンチを回すとそれだけで 5,000 点出る

12:00 まで

Sequel proをMySQLの本番環境に繋げると落ちて辛い。MySQLのバージョンが新しすぎて安定版では繋がらないのだろうという話になり、Sequel proの最新buildを使ってみると無事繋がる。

/info が支配的であることはわかる。ロウソクチャートを作るためのSQLが重たい事はわかるので、計算の仕方をちゃんと理解し始める。

理解が甘いまま高速化を始めたのでここでどうでもいいpull requestを出し始める

秒、分、時間チャートの情報を出すSQLのGROUP BYをしやすくするために CreatedAt だけではなく CreatedAtSec, CreatedAtMin, CreatedAtHou を追加している。

ちゃんとコードを読むと分かるのだがそこはボトルネックではない。

途中で気づいたものの、害はないのでそのままマージすることにする。

ここでEXPLAINした時にtableがpartitioningされていることに気づくがスルーする。実際はここでスルーすべきではなかった。

isucon.net 講評にかいてあるので詳細はこちらをどうぞ。

13:00 まで

なんか分からないけどGoLand上でisucoinが動かない、listenはしているようだが全てのリクエストにたいして404を返している様子。パソコンが何もわからない…

最終的にはロードバランシングが必要でしょうということでchibieggが準備し始める。

この時点でサーバ01でNginx+App、サーバ02でMySQL、サーバ03と04でApp、という構成に。

ただし、Initializeが全台に対して行われるための仕組みを作っていなかったので、いつでもロードバランスできる状態にはしておきつつ、一旦サーバ01だけで処理するようにしておきました。

ローソクチャート以外に他の人にやってもらえる作業としてisuloggerのbulk requestを挙げた、間違いなく8時間以内に上限に引っかかるので、今やっても後でやっても変わらない。(chibieggにしてもらう) 結果6,000点になった。

14:00 まで

なんか分からないけどGoLand上でisucoinが動かない、listenはしているようだが全てのリクエストにたいして404を返している様子。パソコンが何もわからない…(再)

もう諦めてGoLandはただのエディタとして扱う事を心に決める、結果本番環境以外無くなって構成がスッキリしたと前向きに捉える。

初期化を全ノードに実行できる準備 #11

ロードバランスを再度有効化 #12

ベンチマーカーは実行開始前に一度だけ /initialize を実行します。

ロードバランスするとこの初期化リクエストは1つのアプリケーションプロセスにのみ届きます。

その時点で、全てのアプリケーションプロセスを初期化する必要があるため、内部APIを用意し (/internalInitialize) 全てのサーバの初期化を行うように実装しました。

また、設定をsettingテーブルから都度参照するようになっていたのをやめ、グローバル変数に持つように改修することでDBへのアクセスを減らしています。

ちゃんと動作はするようになったものの、数百程度のスコア上昇しかおきませんでした。

大体書いて、何故か手元で動かないので本番でchibiegg達にdebug、bug fixしてもらう。

その間暇なのでuser tableを見ていたら不要なlockがあるので消す。

15:00 まで

みそでんがSNSシェアを有効にするフラグがあると発言。(さすがエスパー担当)

そういえばそんなものがあった気がしてきた、MySQL, Go App ともに負荷が少なくて不思議に思っていたところだった。

あまりにもtrueを返しすぎると、ユーザー増加に耐えられずタイムアウトが増えてしまうので、とりあえず1/8の確率でtrueを返すようにする。

スコアが1万点を超えるリクエストが増えたことでボトルネックがわかりやすくなった

16:00 まで

実装が重たそうなので敬遠していたが、どうしても必要に見えたのでローソクチャートのキャッシュに着手した。

雑じゃないロウソク足のキャッシュ by chibiegg · Pull Request #16 · chibiegg/isucon8-final-app · GitHub

特にバグも無く動作したとchibieggは書いているが、コミットログを見ると、きちんとバグっていたので2回bug fixをコミットしていることが分かる。

雑な /info キャッシュ #15 雑じゃないロウソク足のキャッシュ #16

ローソク足は、直近のものは変化するが過去のものは変化しないローソク足は、秒単位で更新されれば良いという性質もと、私が雑にレスポンス丸ごとメモリにキャッシュする実装、まーす先生が丁寧にロウソク足をメモリにキャッシュする方法をそれぞれ実装しました。

私の雑なキャッシュでも特に問題はなく、一気に25000点弱に。

まーす先生の丁寧なキャッシュもバグ無く動作したため、両方をマージしました。

これがちゃんと動いたので /order の RunTrade に手を入れ始める。とりあえず不要なロジックを消すと 30,000点弱になる。 remove some checks by chibiegg · Pull Request #18 · chibiegg/isucon8-final-app · GitHub

編集がコンフリクトしないであろうUserのアプリケーション側でのキャッシュをchibieggにお願いする。

多少改善したがやはりRunTradeのSQLが重たそうに見える。なんとなくだがRunTradeが走った回数と約定が発生した回数に大きな開きがあるのではと感じ始める。実際にログを仕込んだところ、精々10%ほどしか実際に約定処理が行われていないことがわかった。

このあたりでGo Appのプロファイリングを行ったところ99%がbcryptの処理であることが分かった(もう少し早めにプロファイリングをするべきかもしれない…？)

bcryptを外すと怒られるのでbcryptのコスト(回数)を10から4に落としたものの大差なし。ISUCON8の講評にはこれが効くと書いてあるが… おそらく/orderか/infoの方がボトルネックだった為効果を実感出来なかった…？

17:00 まで

ユーザーの情報をメモリにキャッシュの実装(chibiegg)が終わって30,000点を超える

RunTradeは /orderのPost requestとは別に行うようにしたところ 37,000点程に上昇する。

17:30 まで

ここまで終わったところ、どうも/orderの高速化は頭打ちで/infoのアクセス回数も多いことからなんとかならないかと頭を捻る。

正直やりたくなかったのだが最低売却/最高購入価格のキャッシュを入れたところ 50,000点を超える。 1秒キャッシュしてもよかったのか…

18:00 まで

ようやく再起動テストを始める。アプリに問題が発生する要素はないのでMySQLの対策。 MySQLを再起動するたびに35,000~40,000点になるのでMySQLを温めるコードをchibieggが書く。実際にサーバーの再起動して確かめる時間は無かったのでこれは行わず。しかし実際はサーバー再起動が大きく影響を与えたようで、結果論になるがこちらに力を入れるべきだった。

結果

30,000点程度に落ちて2位、無念。 MySQLを温めるスクリプトが足りていないだけでなく、MySQLの使うファイルがキャッシュに乗っていないのが大打撃となった模様。

感想

勝てなかった。もう少しちゃんとしていれば100,000点は本番中でも超えられたと思うので無念。

POST /signin のBanは実装していなかったがこれも実装すべきだった。

講評より

一方、競技時間中に最大スコアを記録し、惜しくも2位となった「takedashi」は上記で言うところの完全クリアまでたどり着いているようでした。

しかし、再起動試験においてエラーが多発し、1度目はtimeout多発によるfail、2度目はstatus codeが400で返ってくるという事態が発生し減点により結果を伸ばすことができませんでした。(htmlが返ってきていたのでアプリケーションの問題ではなさそうということしか原因はわかりませんでした。)

rebootによる再起動試験をしていたら、もしかしたら競技時間中に気づくことができたかもしれませんが、気づいたとしても対策できるような問題でも無い気がしますので、これもまたISUCONの面白さではないでしょうか？

"気づいたとしても対策できるような問題でも無い気がします" の部分に同意します。取れる対策としてはもっと点数を上げることでしょうか…？ 100,000点を超えていればエラー多発でも完走すれば50,000点は出ていただろうと思います。

またこちらも結果論ですが、userのbcrypt以外はmySQLは不要な問題だったと思うので、ISUCON名物のオンメモリ戦略を取るべきだったかなとも少し思っています。