一人でひっそりとISUCON13に参加していました (5万点でFailしました)

さて今年も残すところあと3週間。11月末にISUCON13がありまして、その直後からシンガポールに5泊6日で遊びにいってた関係でISUCONのブログを書くのがすっかり遅くなってしまいました。今年のチームメイトは… いません! ISUCON9以来の一人参加です。チーム名はinit Sでした。昔からLinuxをこねくり回して壊していた人にはおなじみのシングルユーザーモードに入るコマンドから取った名前です。acidlemon is entering single user mode. ということです。

ISUCON9のときは「いやー一人でやるのは明らかに手が足りなすぎてしんどすぎる。もう一人ではやらない」って思ってた気がするんですが(実際点数も全然伸びた記憶がない)、人は喉元過ぎれば熱さを忘れる生き物ということでまたもや一人で出てしまいました。

結果から言うと、最終スコアは51172ということで上位30位ラインのボーダー付近だったのですが、最後のこのスコアを出すためにいれたtagsのキャッシュがちょっとミスっており再起動後の試験(目視確認)でNGになる感じで失格という感じでした。まぁ、目視確認やってもらえるレベルのスコアが出てたという点ではそれなりに健闘できたかなというところです。

はじまるまで

一人で出るとなにが大変かというと、とにかくチームメイトに組長がいないというのに尽きます。組長いればアカウントつくったりhosts設定したりデプロイ設定したり細かいところキャッシュしたり全部やってもらえる(もちろん自分でやるよりも手が早い)のでデカイボトルネックに集中できるんだよな～ というところなんですが、今回はいつの間にかアドバイザーで運営側に入ってたようなのでしかたない。まこぴーさんもそーだいさんと組んでるし、ということで、初動なにするかとか組長が普段やってくれていることを自分で出来るようにする訓練だけやっておくことにしました。

さくらのクラウドクーポンを作ってISUCON11予選の環境をつくり、ちゃんとインスタンス3台+ベンチ1台を用意して、そこから初動の訓練をちょろっとだけ数日前からやりました。

• とりあえず手元でSSH鍵つくって送り込んで相互SSHできるようにする
• apt install で色々入れる(dstat, netdata, percona-toolkit, net-toolsなど)
• mysqlの設定を変えて別のホストからつながるようにする(bind-addressとrename userらへん)
• mysqlのslowlogいれかたを復習する
• 各種ログをローテーションする方法調べておく(nginx, mysqlなど、お作法がそれぞれ決まってる)
• nginxのaccess.logをJSONで吐いてalpで集計する手順を確認しておく

アプリをどう高速かするかとかは練習してもしかたがないので、ひとまずお決まりの頻出インフラ系タスクを当日悩まないように復習したという感じですね。

あとはisucon13リポジトリを作ってお手元にcloneしておいて、当日を迎えました。

10:00-12:00 はじまったぞ

まずは初動…ということで、事前に訓練したサーバのセットアップなどなどから作業開始。上に書いたいろいろの他に

• EBSを暖める sudo dd if=/dev/nvme0n1 of=/dev/null bs=1M
  • 今回40GBくらいのEBSだったので、約10分程度かかった
  • EBS暖めながらレギュレーション読んだり初期ベンチまわしたりしてた
• どうせいつかやることになるはずなのでmysqlを3台目に分離
  • nginxで /initialize を1回isu03に向けたりしたが、後にinit.shみたらちゃんとホスト指定で初期化できることが分かったので戻した
• サーバから必要そうなファイルを回収してgithub repoに格納 (acidlemon/isucon13)
  • 事前につくった各種スクリプトもrepoに投入してサーバに送り込めるようにする
• init.sh では 10_schema.sql を流し込んでいなかったので、DROP TABLE IF EXISTSしつつスキーマを毎回initializeで流し込み直すようにする

などをやりつつ、初期のpt-query-digestとかalpを眺めてサクッと張れそうなINDEXを張りました。

12:00-13:00 アイコンどうにかする

最初から3台構成でデプロイできるようにする前提で下準備をしたのでまぁまぁ手間取りつつ、さっそく高速化していきます。

まずは、DBにアイコンをバイナリで突っ込んでいる postIconHandler がみるからにヤバそうなのでファイルに書くように対処していきます。

• INSERTしてそのLastInsertIdを返しているけど、使われてなさそうなので固定で32とか適当に返す dd2916bf
• ファイルにかく 0f3e4cb2
• init.shに rm -rf ../img/user*.jpg を仕込んでちゃんと消す 02ebcbbd

ここで、sha256毎回出してるのも無駄じゃろということで、ファイル名にsha256を含めて保存する 171732e8 という小技を使いました。アイコン周りは1時間くらいかけて一旦どうにかなりました。

この手の画像がDBに入る問題はISUCONだと頻出問題な感じですが、今回優しいなあとおもったのは初期データの時点では icons テーブルがなんと空っぽということで、初期状態のDBから画像データを吸い出してstatic fileのディレクトリに置き直す…というちょっと面倒な作業が発生しなかったというところです。

アイコンが片付いたところで10000点を超えました。

13:00-14:00 ヤバそうなクエリをちょっとずつ削っていく

アイコン周りが片付いたところで、DBのヤバそうなクエリが時間使ってるクエリの上位に出てきたので、ちょっとずつそれに対処していきます。まずはstatsから。

• 必要なINDEXをはる & usersから引いてJOINしているけどuser_idをCOUNT(*)すればいいのでusersをJOINしない b9681877

このstatsは明らかにループクエリなんですが、usersのJOINをやめるだけでちょっと負荷がさがるので、次にいきます。次に手をつけたのはダークモード関連です。13:30くらいからベンチマーカーが不調になりましたが、ひとまずこれくらいはサクッといけるはずということで動作確認なしで投入していきました。

• themesテーブルはusersテーブルに結合して問題無さそうなので結合しちゃう 11257d2e
• initial_users.sql に update users JOIN themes t on t.user_id = users.id SET users.dark_mode = t.dark_mode; を入れて初期データのthemesのデータをusersテーブルに反映 4337869d

14:00-15:30 ベンチが止まり、キューが混雑して試行錯誤に時間がかかる

おにぎりを食べながらレギュレーションを読んでいると、アイコンについてはGETするときにConditional GETしていて別のAPIで返しておいたicon_hashと変わってなければ304返すことが出来る というのがあるのでそれに対応しました dc1a2e88。で、これでOKかなとおもってnginxのアクセスログを確認しましたが304を返している形跡がなく、なんでやねんとおもったらダブルクォーテーションで囲まれているのでそれは取り除く必要がある、というやつでした 30354bcf 。ETag的なやつだから囲まれていた…ということですかね。

sqlxは普段ほとんど使わないのでstructに詰めるところを書くのが苦手なんですが、そうも言っていられないということでインラインにstructを定義してN+1クエリを解消してゴリッと1クエリで全部とるようにし、ランキングは元のロジックの集計するように修正しました 0ebf65ba。ハマることなくこれが一発でうごいたので結構自分で自分を褒めています。

14:30-16:00 DNSのことを考えはじめる

この辺まで来たところで、PowerDNSの負荷もだいぶ上がってきたので、いろいろ手を打ちました。

• PowerDNSのプロセスは1台目のまま、mysqlだけ2台目に逃がす
  • /etc/powerdns/pdns.d/gmysql-host.conf に設定があるので gmysql-host=192.168.0.12 に書き換え
• そもそもisudnsに大事なINDEXがないので追加
  • alter table records add index idx_records_name (name);

PowerDNSを1台目のままにしてあった理由はユーザ追加時に pdnsutil add-record というコマンドを打っているからなので、これもAPIアクセスに変更しました 323293e1。これで理論上はいい感じにプロセスを別サーバに分離できそうでしたが、pdnsのAPIがlocalhostからしかいけなさそうなのでbindするアドレス変更とかまで調べる時間が惜しいのでDBだけ分離したまま1台目にプロセスを置きました。

このほかにもPowerDNSの設定で cache-ttl=90 と query-cache-ttl=90 あたりをいれたり、レコード追加するときのTTLも0じゃなくしたりなどの指定を入れてました。この辺をやっていくと、

• 1台目: nginx, isupipe, pdns でCPU100%
• 2台目: mysql(isudns) でCPU80%
• 3台目: mysql(isupipe) でCPU90%

という感じになり、WebAppとpdnsが同居している弊害が出始めます。

16:00-17:00 WebAppの負荷を下げる

明らかにまだDB側にヤバイクエリ飛んでいるのにWebApp側のCPUがボトルネックになっているのはマズい、ということで、色々小手先の変更を入れて負荷を下げていきます。

• SetMaxDBConnを増やしてDB側によりたくさん接続する dd2a3466
  • 並列数上がって走行パターン変わるかなとおもったけどあんまり効果なし
• goccy/go-jsonへ変更 1b0fdd5f
• デフォルトの画像もちゃんとIf-None-Matchで304返す 99062865
• isupipeのCPU負荷をちょっとでもヒマしている2台目に逃がすべくnginxのupstream設定をいろいろ入れる
  • この時点ではicon_hashをファイル名に入れていた関係で別ホストに逃がせないので、レスポンスにicon_hashを入れないエンドポイントだけ2台目に逃がす、というlocationをたくさん書きました nginx: isupipe.conf

ここまでやってもあまり有効打にならないということで、あえてDB側に負荷が寄るように画像のsha256のキャッシュメカニズムをファイル名からusersテーブルの追加カラムに変更 13c2b2b7というのをやったところ、WebApp側の負荷がガッと下がってまた3台目のisupipe MySQLにボトルネックが移りました。ここでスコアがゴリっと上がったので、「Globでファイル名リスティングするの重かったか～～」となりました。これで17000点くらいから30000点くらいまであがりました。

17:00-18:00 ラストスパートしていく

これで、DNSとアイコンがきちんと片付いた状態になったので、ここからまたisupipe DBに飛んでいるクエリをpt-query-digestで見ていって、足りないINDEXをポチポチ追加していきました。

• ngwordsのINDEX追加 f6a13085
• livecommentsのINDEX追加 f7fc9fde

で、ここまでやったところで17時半、38000点くらい。もうちょっと一押ししたいけどslowlog的にホットになっているもう1個のstatsのN+1クエリを潰している時間はない…ということで、この後に及んで更新がまったくない事に気付いたtagsをオンメモリキャッシュすることにしました。

なぜか何回かFailして、一部キャッシュするのを諦めるとなんとかベンチが通り、50000点に乗りました。今回は競技時間中の最終計測スコアが最終スコアになるというレギュレーションなので、netdataをアンインストールしたり各種ログを全部止めたりして2～3回回すと51172点が出たので、ここで作業終了。再起動して動かなくなる要素はないはずなので再起動試験はなし!で18時を迎えました。

で、結果発表のあとにインスタンスのログをみると、なんか計測してそうな時間に502エラーが出ている…。panicしているところのログをみていくと、「EC2が再起動されたあとに /initialize を呼ばずにtagsを読むとキャッシュに何ものってないのでOut Of Boundsなエラーがでる」というバグを最後に仕込んでしまったことがわかり、上位チームに対する事後整合性チェックでFail扱いになってしまいました。

51,172　init S　(再起動後のデータチェックで不整合があったため)

競技が終わった後に、感想戦でtagsはそもそもDBから読むまでもなくGoのファイルにsliceでハードコードしてもいけてしまう、ということがわかり、いやーこれはもったいないことしたな～～ と思いました。そこちゃんと出来ていればギリギリ30位以内に入れたスコアなので、だいぶ惜しかったという感じです。まぁこの辺レビューとかで担保できなかったのは、一人でやっていることのつらさですよね。

おわりに

Failで終わったわけですが、それにしても一人で特別賞ラインの5万点くらいいくのはまぁがんばったほうなんじゃないか…と思いました。ベンチマークが50分くらい止まったり、その後もキューイングの待たされ方にムラがあったりはしましたが、自分はそれによって大きく時間を無駄にしたりはしなかったのでその点はよかったなというところです。

あとはアレですね、アイコンのハッシュをファイル名に入れるっていうのはちょっとよくばりすぎましたね。最初からシュッとusersテーブルにいれておけばよかったです。その辺最初からusersにいれとけばstatsのN+1バラしはもうちょっと進んだはずなので、あと2～3万点くらいは上乗せできたのではないか…と思いました。そのほか色々思ったのは

• singleflightをゴリゴリ打ち込んで優勝したこともある人間ですが、今回はsingleflightが有効な箇所はあんまりなかったなと思っています。もちろんキャッシュしたほうがスコア上がりそうな部分はありましたが、singleflightの旨味はキャッシュもそうですがめっちゃ長い処理がthundering herdしちゃうときに1本しか同時に走らないようにするという同時実行数制御だと思っているので、statsがそんなに高頻度に呼ばれない今回はそこまで旨味なかったかなと思います
• 感想ブログ読んでくとDNSをzone-fileで処理する関係でregisterを直列化したので伸びなかった的なのがあり、なるほどなあと思いながら読みました。うちは参考実装のままPowerDNS + MySQLにしておいて、INDEX追加してDNSプロセスとDBプロセスを物理的に分離することでDNS関連でCPUを300%程度消費していたのと、register時のレコード追加もコマンド実行からAPI実行に変えたのでそこのスループットはよさそう。ベンチ1回でアップロードされた画像の番号が1900くらいまでは行ってたはずなので、registerがおそらく900回くらいは回ってたようです
• 今回は(別に批判的なニュアンスではなく)スコアリングが不明瞭な感じでした。マニュアルにはいろいろ書いてあるけど、どのエンドポイントをどうすれば点数が直接的にあがる、みたいなのは全然わかりませんでした。tipされたときのレコードを見ていくと、5点、10点、100点みたいなレコードはあったので、特定のシナリオに従ってtipする量が増えるんだなくらいはわかりましたが、どこかを集中的に早くすることで点数をガガッと稼ぐみたいなのは難しかったな～と思います。結果的にそういう特定のエンドポイントをめちゃ早くするみたいなことをせずにボトルネックを上から潰していった自分のところはやってる手数の割にはスコア伸びてる方なんじゃないか、と思いました

ということで、今年のISUCONはおわり! それではまたお会いしましょう～