ISUCON10予選に参加した(落ちた)

ISUCON初参加勢 @moajoと@kyasbalと共にチーム王数件で参加してきました。言語はtypescriptかGoで迷い、並行処理やるならGoっしょとのことでGoになった。

@moajo視点の記事はこちら

ちなみに王数件は、大学学部時代に所属していた部活である応用数学研究部もとい応数研から。変換めんどくさいのよね

役割分担は各々特別この分野に強いというよりは満遍なくどれも触れる感じだったので、ある程度の方針を最初に決めつつあとは流れでみたいな風だった。一応前もって方針みたいなのはメモって残しておいてあった。

f:id:coil398:20200913005518p:plain

大体この感じで、最終的にはmoajoはコードを読みつつ最適化できそうな部分を片っ端から直していき、kyasbalはキャッシュ周りとクエリの最適化を行い、自分はログやCPU使用率などの監視から方針を考えつつnginxやMySQLのミドルウェアの設定を行うといった分担になっていた。コードのコンフリクトの点からも分担は必要みたいな記事を見かけたのでこれは正解だったように思う。

よくisuconの参加者ブログにある?自チームの得点遷移のグラフみたいなのはないので、20:00時点でのリーダーボードを貼っておく。

f:id:coil398:20200913004822p:plain
午後8持時点でのリーダーボード(おや、0という数字は...?)

とりあえず割と決め打ちで二人を誘いつつISUCONに申し込んだ感じ。事前練習は二ヶ月くらい前にISUCON8の予選を一日かけてだらだらとやったのと 一週間くらい前にISUCON9の予選を見た程度で、あとは各々過去の参加者が何をしていたか、どうログを利用していたかを記事読んでた。

当日はなんやかんやで時間が変わり12:20~21:00まで、と言っても途中ベンチマークがサーバーエラーで動かずに方針を立てるだけの時間帯であったりがあったので 実際に手を動かしていた時間はもう少し短い。と言ってもなんだかんだ全員ほぼほぼ休憩取らずにぶっ続けで作業してたなぁ。もちろんトイレ行ったりはあったけど。これがADHD特有の過集中だ!

当日の流れを思い出せる感じで書いていく。

12:20~15:00

時間帯はある程度適当である。 まずは全員でレギュレーションを読みつつ、ログを仕込みながらベンチを回して方針を立てる算段だった。 ただしこの頃はベンチマーカーがロクに動かず、なにか設定を変えようにも検証のしようがないので主にコードを眺めつつひたすら方針を練っていた。 ログ周りを仕込んだのもこのあたり。 alp用にnginxのアクセスログのフォーマット、mysqlのスロークエリの設定、GCPのスタックドライバー用のコードの埋め込み、各種ツールのインストール(alp, myprofiler, lltsv, kataribe, query digestをインストールしたが、結局使ったのはalpくらいだったかな)もついでに行っておく。

f:id:coil398:20200913010341p:plain
alpの出力結果

searchとlow_priced, nazotteあたりが怪しい。

加えてレギュレーションからbotによるアクセス、MySQLのクエリあたりが怪しいそうだなと目処をつけていった。 botによるアクセスはご丁寧にレギュレーションにこういった正規表現で弾けるよと書いてあった。Goの正規表現は遅いという話があるのでGoを狙い撃ちしたのかな?と邪推する。

しかしここで困ったことがあった。今回の題材はisuumoと呼ばれる「椅子に対していい感じの物件を提供する」サービスなのだが、過去のISUCONとは異なりmain.goのファイル自体は1000行程度の非常にシンプルなものだった。 テーブルもchairとestateの2つのみ、クエリも変なものや露骨なN+1などはほとんど見受けられずパット見改善点があまり思い浮かばない。最初数時間ほとんどスコアに開きがなかったので全員同じような状態だろうと推測していた。

ちなみに結果から言うと、今回のISUCONはスコアの上昇というかインフレがかなり抑えられており、割と小手先のテクニックを積み重ねてちょっとずつ点数を伸ばしていく味付けだったと思われる。過去の典型例があまり適用できず、一つ一つ改善点を探してくのは非常に面白かった。ちなみにこの状況は実は予想しようと思えばできた。

employment.en-japan.com

今回の問題、前回優勝チームが一部作っているらしいのだが、その優勝チームに対するインタビュー。要約するととりあえずオンキャッシュすれば点数伸びるよねーみたいな典型例は出したくないと読める。あと競プロのエッセンスも匂わせており、これはまさしくnazotteの最適化である。ISUCONも10回目を迎え(過去のことはほとんど知らないが)あの手この手で問題を出してきてネタが尽きてるみたいな話もある中、個人的にとても良問だったと思う。

この時間帯では細々とした修正をいろいろしたが、ほとんどスコアは動かなかった。

f:id:coil398:20200913011708p:plain

ほとんど動きはしなかったが、結果的に今回のISUCONでは修正に対する点数の伸びはこんなもんだった。

f:id:coil398:20200913012406p:plain
こんな感じの画面でいろいろ見てた(イメージ)
完全に映えを狙っている。

15:00~18:00

この辺りで覚醒をし始める。 ベンチマーク中にCPU使用率を見ていると100%に貼り付いていたので一旦アプリケーションとMySQLを別サーバに分ける。ちなみに今回は3つのインスタンスが与えられていた。

ウェブアプリケーションのCPU使用率が50%程度なのに対して、MySQLの方では100%に貼り付いていた。 ここで、ウェブアプリケーションはLBせず一つのインスタンスで行くことにした。一方インスタンスが一つ余っているが、特に使い道もないので一旦保留にしてしばらくは検証用としていた。 一応3つ目のインスタンスの使い道としてはRedisを考えたが、ウェブアプリケーションの載っているサーバはまだ余力があるしそこに載せてしまえば良さそうだった。

ちなみにここ何回かのISUCONではオプションを変えることで負荷を操作できた。今回もそれらしきものがないか探したが見当たらなく、このへんで今回のISUCONのテーマはデータベースでは?と気付き始める。CPU使用率100%だし。

moajoはこのあたりでnazotteに手を加えるもとい競プロをし、kyasbalはredisにキャッシュを載せてスコアアップを狙っていく。 とはいえ前述したようにMySQLサーバのCPU使用率を見るにここがボトルネックになっている可能性が非常に高い。これは先程目処をつけたエンドポイント群からも明らかだった。 ここでkyasbalよりデータベースの2つのテーブルが分割できそうとの情報を得る。分割ができるのであればシャーディングできるのでは?ここでインスタンス二台にMySQLを置く構成にした。一方がestateテーブル、もう一方がchairテーブルを担当する。 それとスロークエリのログから、適当にインデックスを貼っておく。 これらの試みが実を結び、一気に点数アップして1800ほどまで上がった。ここでようやく25位以内に入ることができた。

続いてGoのMySQLコネクション数を10から20にアップ。(単純計算でDB二台に負荷分散しているので各MySQLインスタンスへのコネクション数を二倍にした) 点数は2000を超え、最高順位5位を達成した。

二台に分散したMySQLだが、ベンチをとってみると両者ともに高いCPU使用率(↑90%)であり、シャーディングは必須だったと思われる。そしてさらなるボトルネックの解消が望まれた。 シャーディングついでにデータベースの初期化処理をgoroutineで並行化したが、あくまで初期化処理なのでスコアへの寄与はなかったはず。

その頃kyasbalが大きな変更点を思いつき、暗雲立ち込めたイケイケだった彼はさらなるスコアアップを狙いに行く。

18:00~21:00

とはいえラストスパートであり、再起動試験やデバッグを考えて1時間のバッファを取ると考えると使える時間は少なく、自分は細かい設定変更を行っていた。 一方でmoajoとkyasbalは前述の変更点に突き進み絶賛実装中だった。俺「絶対にバグらせんなよ!!!!!!」kyasbal「任せろ!!!!!」

まずはGoとMySQLのコネクション数、これについては数値を変えてはベンチを回しを繰り返したが、エラーでスコアダウンを繰り返したために泥沼化を恐れて20固定とした。 nginx.confについては静的ファイルについてキャッシュを入れてみたがスコアが下がってしまった。 MySQLについては設定変更する時間がなく断念、だがしかし思えば今回はミドルウェアの設定についてはもしかして変更する余地がなかったのではと思う。 実際nginx.confは変に設定を弄ってスコアが下がったと述べているチームが他にもあった。実際は知らんが。 ついでにいろいろ埋め込んでいたログ用のコードを取っ払った。

結局kyasbalのデバッグは終わらず、再起動試験もできず(自分は何度もリバート!と叫んでいたのだが) あろうことかkyasbalがinitializeで入れるsqlデータをぶっ壊していることに終盤気付く。しかも悪いことにmasterブランチにマージ済だった。合掌 どの時点で壊れたか検討もつかないので、かろうじて残っていた他のブランチを必死に漁り、なんとか動くものを見つけてcherry-pickしてデプロイした。

ラスト10分にベンチのエラーを確認し、5分でcherry-pickしてなんとか動くブランチを作り、デプロイしてベンチを回す経験をしたことはあるか?俺はある。

f:id:coil398:20200913015114p:plain
心臓に悪い30分間だった。

なんかよくわからなくても何かしらの"ツラミ"が伝わってくれれば幸いである。

最終スコア1832を記録して俺達のISUCON10は終了した。

あ、本戦出場はだめでした。ちゃんちゃん

再起動再試通ったんかなぁ。それだけが気がかりである。

参加者の皆さん、運営の皆さんお疲れ様でした!!! 来年リベンジしますぞ