ISUCON10決勝に並行チームとしてfujiwara組で参加してきました

先日「ISUCON10、予選で敗退した〜」というブログをかいたのですが、その後運営チームより「本戦のライブイベントで『本戦参加者と並列で解くエキシビション的なチーム』として参加しませんか!」というお誘いがあり、決勝の日はまだバッチリ開けてあったので「はい! 出ます!」ということで参加しました〜というレポートです。

結果

ライブ配信時に発表されたスコアとはちょっと異なってますが最終結果はこんな感じになっているそうです。

予選敗退勢の並行チームは4チームいて、ベストスコアと最終計測スコアはこんな感じ。

ざっくりいうとfujiwara組は本戦でいうと2位と3位の間くらいでした、いやー予選さえ突破できていればな〜〜。それにしても今年は1〜3位が全部学生というのはすごいですね! 学生枠じゃなくて社会人枠作ったらというジョークもでるくらいの結果でしたが、お題的にもみんな知ってるISUCONということで参加者によってドメイン知識の偏りがなかった結果学生がいかんなく伸びてきたというところなのかなぁと思っています。

ということで、ここからはfujiwara組のやったことの話とかを書いていきます。

始まるまで

並列チームは運営チームより「ミライノタワーに来ますか?」と聞かれまして、「はい! 行きます!」と答えた我々は新宿で参加することにしました。私は鎌倉住まいなので湘南新宿ラインで新宿にいくにあたって9時までに行くには7時半すぎの電車に乗る必要があるので仕事いくよりもよほど早起きが必要でしたが、ISUCONのためなら普通に早起きできるのでその辺は余裕でした。ちなみに朝の検温は36.1度でした! 寝起きだと思ったよりも低い。

さて、朝起きてみると組長からちょっと喉痛いので大事をとって自宅でやりますという連絡がありちょっと想定外でしたが、そんなこともあろうかと持っていく予定の装備にモバイルディスプレイのほかにiPadも入れてあったので、会場ではiPadでHangouts Meetを繋ぎつつ普通に準備完了。あとは開始を待つだけ!

手元にデバイスがたくさんあってハウリングしないようにするためのMeetの準備とかに少し手間取ったので、ライブ配信の最初のお題発表はちゃんと見れなかったのですが、遠くのほうで同じく並列で解くチームのみなさんが「ISUCONのポータルがお題だ……」とざわついていたので「マジか〜」と思いつつ、競技開始になりました。

10:00〜12:00くらい

インフラ構成をチェックしてみると、3台ともスペックが違うことがわかりました。

• isu01: 2コア 1GB
• isu02: 2コア 2GB
• isu03: 4コア 1GB

ということで、isu01が一番しょぼくて、メモリが倍なのが02、コアが倍なのが03という感じ。合計8コアでそのうち03に4コア偏っているので、分散構成にしない(できない)プロセスで、CPUヘビーなやつを03に置くのが良さそうです。

初期ベンチを分析

初期実装はRubyで設定されていて、isu01にベンチをかけてだいたい4000点ちょっと。CPUの偏りとしては、うろ覚えだけどたしかbundle(xsuportalのpuma)2プロセスで50%、mysqlで30%、ruby(benchmark_server)で20% みたいな感じでした。isu02もメモリが増えただけなのでとくに点数は伸びず、isu03はコア数が2倍になっているのでたぶんスコアも伸びるだろうと思ったのですが、isu03もほぼ同じ点数で伸びず。ただ、CPUの負荷の偏りは異なっていて、ruby(benchmark_server)がCPU1コアまるまるつかうようになっていてなんだこれは……みたいな感じです。

そのあと、言語をGoにきりかえて様子をみてみると、初期でスコアは6000点でした。GoにするとプロセスごとのCPU消費割合が異なっていて、Goだとmysqlが圧倒的にCPUを食うようになっていました。結構実装言語ごとにCPUの使われ方が異なる題材だな〜という感じです。このときまだレギュレーションちゃんとよみおわってないので中身も分からない状態でした。

とにもかくにも、初手でミドルウェアのマシンを分散しないとならないな〜という感想になったので、組長にmysqlをisu02に移してもらいました。そのほかいろいろと、12時くらいまでに、毎回やるじゃろ的な設定を入れました。

• mysqldをisu02に移設 (fujiwara)
• binlog止めて、書き込みヘビーなので innodb_flush_log_at_trx_commit = 2 (fujiwara)
• go-mysql-driverの設定で InterpolateParams = true する (acidlemon)

12:00〜14:00

さらに、レギュレーション読んであきらかにコレやった方がいいよね的なの追加でやっていきました。

• /api/audience/dashboard は最大1秒キャッシュできるので、Go上に900msオンメモリキャッシュする(acidlemon)
• レギュレーションに仮想選手の出場人数によるスコアボーナスが載ってたので、TeamCapacity = 15にあげる(acidlemon)
  • このときまだ勘違いしてて、出場選手数は join-member: 30 がそれだとおもってたので15に上げた(後述)
• contest_config が走行中は不変っぽいので、getCurrentContestStatus を90秒キャッシュする (macopy)

インフラ構成とレギュレーションを見ながらゴールイメージを考える

ひとまず、isu02にmysqldを逃がした後isu01でその他のものを動かしていましたが、isu03を使わない理由がないのでisu01にいたxsuportal, envoy, benchmark_serverを4コアのisu03に移設することに。だいたい基本的にISUCONって最終的にはmysqlの負荷を全部下げきってあとはアプリとかのCPU勝負になることが多いですしね。

Rubyのときはbenchmark_serverがisu03だとCPU100%食ってたのでGoでもそうなるのかなとおもいきやそうならなかったものの、おそらくxsuportalが高速になってきたら最終的にはbenchmark_serverをisu01に分離した方がよさそうかな、と目算を立てました。

で、4コアのマシンに乗せるとisu02もisu03もCPUが余ったので、TeamCapacityを60にしました(180人参加)。このときはまだ「TeamCapacity=60だから選手は120人なのでスコア1.4倍」と思ってたんですが、普通にあとからスコアみたら1.6倍になってました。この時点で何回か回して28000点で、本戦参加者からは並列チームのスコアが見えてないですが全チーム中トップになりました。

14:00〜ライブ配信出演

この時点で、/api/audience/dashboard が50秒の走行の間に12000回くらい呼ばれているため、240回/秒くらいのペースということでキャッシュがきれた瞬間におそらくThundering Herdな状態になってそうなので、golang.org/x/sync/singleflightで重複呼び出しを排除する という記事を参考にキャッシュ切れたときのダッシュボード読み直しを直列化しました(macopy)。これでスコアは29000→33000くらいかな。

14時半すぎに決勝ライブ配信に出演して、戻ってくる頃にはなぜかベンチマークが安定しなくなり、どうもenvoyが死んでいる様子。journalctlでsyslogとにらめっこした結果、ちゃんとenvoyの断末魔が記録されており、socket(2) failed, got error: Too many open files とのことで、fd上限あげてもらってまた安定。

ここからちゃんとした戦略を考える

大体半分過ぎたところで問題とレギュレーションはちゃんと理解できました。簡単にいうと

• 仮想選手がベンチを投入し、仮想負荷走行が終わり、通知を送って仮想選手がそれを確認したら10点
• 仮想選手が質問して運営が回答し、それを仮想選手が確認したら10点
• 仮想選手がダッシュボードを表示したら2点

なので、この10点のやつをいかに高速にぶん回すかということになります。また、仮想選手のベンチが1回おわると仮想オーディエンスが1人増えるので、この仮想ベンチマークをもりもり回せるようにするのがよかろう、ということでいくつか手を打っていきました。

ベンチマークジョブを並列取りだしできるようにする

ここで手をつけたのはまだなんにもしてなかったベンチマーカーです。ベンチマーカーは、キューの読み出し部と、スコアの記録部に分かれていて、入り口のキュー読み出し部がよくみると完全直列になっています。どういうことかというと、SELECT * FROM benchmark_jobs WHERE status = 0 ORDER BY id LIMIT 1;でベンチ未実行のジョブを1件取り出すんですが、ジョブの取り出し側は最大でチーム数の数だけ並列度があがるようなことがレギュレーションに書かれているものの、この実装だと並列にポーリングされても

• 複数のRPCで同じIDがよみだされる
• 最初にSELECT 〜 FOR UPDATEでロックを獲得したRPCがステータスを変更してジョブハンドルを返す
• 他のやつらはFOR UPDATEで待たされた上、statusが違ってrowが0行で返るので次のポーリングをする

となってしまっています。ということで、これだと並列に呼び出されても1ジョブずつしか処理されないので、ORDER BY idをORDER BY RAND() に変えて、ジョブの読み出しが並列で走るようにしました。ちなみにスコアは上がったかというとほぼほぼあがらなくて、このときのボトルネックはmysqldのあるisu02のCPUなので、結局mysqlの負荷を下げないと意味がないねということでつぎの作戦へ。

質問回答のところにN+1クエリがあるので撲滅する

macopyがやってくれた! これでまたちょっとmysqlとxsuportalのCPUが空いたので、同時にTeamCapacityを60から90にしました。

これも結果からいうとあんまり変わらなくて、うーんという感じだけど、TeamCapacityを増やすと倍率はあがるけど仮想ベンチの完走数が下がるからっぽいというのはスコアのbreakdownを読んでわかったので、mysqlがもっと楽になるようにあのデカイダッシュボードクエリに手をつけ始めました。

ダッシュボードクエリの計算をちょっと楽にする

この時点で、macopyがWebPushをなんとかすると宣言したのでそれは完全に任せたのと、組長が「静的ファイルをnginxで返したい」ということでnginxチャレンジをして一発で成功させている間、わたしは68行くらいあるダッシュボードの集計クエリに手をつけ始めました。改善できそうなところとしては

• スコアを raw - deduction でSQL上で計算してるので、benchmark_jobsにスコアを保存するときに計算した値を入れる
• 学生チームの判定のためだけにcontestantsテーブルをJOINしてたので、teams側にstudentフラグを保存するようにする
• best_scoreとlatest_scoreを毎回LEFT JOINで集計するのは無駄なので、別テーブルを新規に作ってそこにおく

の3つかな〜と目星をつけて、1個ずつやっていきました。raw - deductionのやつはわりとあっさり片付いて、macopyがWebPushのテストで苦労してる合間にシュッといれて無事高速化に寄与しました。

で、学生判定は17時過ぎから入れてみたモノの、バグがあって通らず、17時半くらいの時点で断念。ちなみにスコアを別テーブルに保存するやつも、普段使わないechoとかでやりきる自信が全然なかったのでそのまま手をつけずにやめました。

学生判定は、studentフラグが関係するのは「CreateTeamしたとき」「JoinTeamしたとき」「UpdateRegistrationしたとき」「DeleteRegistrationしたとき」の4つなんですが、UpdateRegistrationとDeleteRegistrationに相当するPUTとDELETEの/api/registrationは集計されたalpログを見る限りベンチマークで呼び出してないっぽいので、「CreateTeamしたときにStudentが作ってたらTeamにフラグを立てる」「JoinTeamしたときに、Studentフラグのチームで入ってきた人がStudentじゃなかったらフラグを落とす」で実装しました。

で、これで普通にいけるとおもってたのでこれ以上わからんということでブランチを破棄したんですが、今になってコードをよく読むと既にどっかのチームに入ってる人がJoinTeamを呼び出したときにとくにどっかに所属してるかとかノーチェックでUPDATE文を発行しているので、その元いたチームから社会人が抜けて移籍して元のチームが学生だけのチームになったみたいなパターンがありますな! いやーそこまでケアしてなかったわ〜。

17:00すぎて、最後の追い込み

ということで、最後の追い込みだったのですが、なんと17時〜17時40分までベンチが全部フェイルしまして、さすがにこれはしんどい。フェイルしてた理由はいくつかあり、

• WebPushがどうしてもなんか「受け取るべき通知エラー」で安定しなかったので、結局WebPushは無効状態に戻した
• 学生判定が出来なくて通らなかった
• envoyからnginxに変えた後からHTTP2 GOAWAYフレームがどうのこうのというのが実ベンチマーカーまで返されてしまい、めっちゃ減点された
• TeamCapacityを120まであげたら負荷が高くなりすぎていた

というあたりだったので、WebPushは最終的に無効に、学生判定は切り戻し、nginxもenvoyに戻してもらいました。

TeamCapacityについては、17時過ぎにTeamCapacityから想定してた仮想選手人数と、実際のスコアリングのボーナス係数が異なることに気がついて運営に質問をしたんですが、直後に「あれ、これはCreateTeamで1人、JoinTeamで2人で合計3人チームなのでは……? ということはTeamCapacityの2倍ではなく3倍が仮想選手人数なのでは……?」と気付きました。そのときTeamCapacity=120で係数が2.0倍だったんですが、300人以上は一律で係数2.0になるので、こんなにTeamCapacityあげる意味無いな〜ということで100に落としたら無事スコアが安定し、最後に再起動試験をやって作業終了となりました。

結局Studentを倒せなかったのでisu02のmysqlのCPUボトルネックというところは変わらなかったのですが、でもmysqlも200%弱食ってるしxsuportalも200%前後食ってるので、たぶんこれはisu02と03の役割を入れ替えてもそんなに変わらなかったかなという印象。golang内のキャッシュのアレもあったりしてxsuportalを2台(2プロセス)に分散するのは時間内にやろうとするとたぶんハマるだろうと読んで、手をつけませんでした。envoyとbenchmark_serverもisu03においたままです。

isu03が4コアあるというのは本当に便利で、この状態ではenvoyはisu03に同居してもCPUあまるくらいなので、静的ファイルをxsuportalからenvoyに返すためのサーバ間ネットワークオーバーヘッドも不要なこの構成でいいかな〜というところでした。

ただこれ、mysqldのCPUを本当に完全にカツカツに使い切ってしまうといろいろと遅延して最後の検証処理で死んだりdashboardの反映遅延のペナルティが出たりとかあるので、TeamCapacity=100でちょうどバランスとれてよかったな〜というところです。

まとめ

いやーお題がお題なだけに楽しかった! あと、本戦のライブ配信の並行チーム紹介のときにわたし「本戦チームの3番目くらいに入っておきたいな〜」って言ってたんですが、まさに有言実行ということでがんばったかいがあったな〜 と思いました。まさか1〜3位まで学生だとは思いませんでしたが……。

それでは、また来年のISUCONでお会いしましょう〜。