はじめに

「手が3本あるテディーベア」(@Azon、@xxpoxx、@mazrean)というチームでISUCON11予選に参加し、学生枠で予選突破しました。
Go言語を使用し、参考スコアは80370です。

事前準備

2度の部内ISUCONで練習を行いました。
2度とも最初に数時間チームで解き、チームでの動きを練習しました。

Makefileは@Azonが普段使っているツールのインストールや計測まわりが楽に行えるようにされているものを用いました。
また、計測結果はslackcatを用いて全てslackへ投げられ、後から見返せるようにしていました。

役割分担は初動に関しては

• @Azon
  • ツール類やgitのセットアップ
  • DB、Nginx、カーネルパラメーターの流し込み
• @xxpoxx
  • アプリケーションのコード読み
• @mazrean
  • マニュアル読み

のようにしていました。
それ以降は特に決めずに、全員DB、Nginx、アプリケーションなど関係なく誰も手のつけていない中で優先順位が高いものに手をつけていくような形で動いていました。

当日

チャット、通話ともにDiscordを用いてリモートで参加しました。
slackは計測結果の確認のみに使っていました。

10:00

競技開始。
@xxpoxxがCloudFormationでインスタンスを立てた後、
練習での役割分担の通り、@Azonがサーバーに入り、@xxpoxxがアプリケーションのコード読み、@mazreanがマニュアル読みを開始しました。

10:40頃

それぞれ初動でやる作業が終了し、初回ベンチマークを回しました。
結果、postIsuConditionが重いことがわかり、
マニュアル内の

POST /api/condition/:jia_isu_uuid で受け取ったコンディションの反映が一部エンドポイントで遅れることをベンチマーカーは許容

という文面も踏まえてworkerで非同期に処理する実装を@mazreanが開始します。
この時実装を開始したworkerはinsertを1つずつ行うものでした。

この時点だと他のボトルネックがあまり見えていなかったというのもあり、
@AzonはNginxの静的配信周りのgzip圧縮やキャッシュの調整、
@xxpoxxはkataribeの出力を綺麗にする作業に入りました。

11:40頃

それぞれの作業が終わった@Azonや@xxpoxxにバグとりを手伝ってもらい、@mazreanがworkerの実装を終えます。
この時点でpostIsuConditionのdropを行う処理をコメントアウトします。

この時点でgetTrend、getIsuIconが遅いことがわかったので、
@AzonがgetTrendのN+1の修正、
@xxpoxxがGET /api/isu/*/iconのキャッシュに取り掛かります。

手が空いた@mazreanはpt-query-digestでadministrator command: Prepareが出現しているのを見てinterpolateParams=trueしたり、getTrend、getIsuIconと比べると大したことがないもののpprofに出てきていたgetIsuListのN+1を雑にmapを用いて改善したりしはじめました。

13:20頃

getIsuTrendのN+1が消えたり、GET /api/isu/*/iconをCache-Controlでキャッシュしたり、getIsuListのN+1を修正したり終わります。
しかし、あまり点数は上がりませんでした。

ここで点数が上がらない原因について一度落ち着いて考えます。
まず、最初に思い出したのがスコアの計算方法が新規コンディション数に応じてされることです。
最初に行ったpostIsuConditionの非同期化が1つずつのinsertであったために遅く、
反映される数が少ないのではないかということに思い当たりました。
conditionのinsert用のworkerでbulk insertを行うようにするのに@mazreanが着手しました。
次に計測結果を見て気になったのがgetTrendの負荷が思っていたより下がっていない点です。
これを鑑みて@AzonがgetTrendがgetTrendでのetagの実装、trendを0.5sごとに更新するworkerを立て、getTrendではその結果を返すのみにするのに着手しました。
手が空いた@xxpoxxはconfigがオンメモリキャッシュできることに気がついたため、僅かでも効果があるのを期待したconfigのオンメモリキャッシュを始めました。

13:50頃

postIsuConditionの非同期改善、getTrendの改善ともに終わり、20000点前後まで上がります。

ここで@mazreanがmapでのN+1潰しをしたgetIsuListがクエリの結果が多いために重くなり、@AzonがしっかりJOINでN+1を潰す修正をはじめます。

@xxpoxxと@mazreanはgetIsuListの次に重いgetIsuConditionが遅い原因の調査をはじめます。
結果、返す値の多いクエリに対しアプリケーション内でconditionから無の値を用いて絞り込みを行なった後、limitをかけていることが発覚します。
これをために@mazreanがcondition_levelカラムを追加してクエリ内でlimitまで行えるようにする修正を開始します。

15:00頃

getIsuListの修正が終わり、26000程度になります。

@AzonはgetTrendでetagがうまく動いていないことに気づき、その修正を行った後、@xxpoxxと一緒に複数台構成へ着手します。

17:10頃

@mazreanがバグりにバグらせていたgetIsuConditionの修正が完了し、一気に50000点台まで上がります。

既に本来の競技時間終了まで1時間を切っており、再起動試験を行うか、
バグらせていた複数台構成をそのまま続けるかの判断を迫られていました。
この時、学生枠で5万点を超えているチームは4チームほどであったため、
複数台構成を諦めて再起動試験対策をした方が学生枠での通過の可能性が高いと判断して再起動試験対策に移ります。

再起動試験に着手したタイミングで今まで残したたままだったアプリケーションのログを含む全てのログを切ります。

17:15頃

ポータルが504で開けなくなることが多くなります。
この中で奇跡的に1度ベンチマークを叩くことができ、それが80000点を超えます。
アプリケーションは全てのリクエストのログを吐いていたため、思っていた以上に影響が大きかったのだと思います。
この時点で再起動試験に落ちさえしなければ学生枠のラインを越えるのを確信し、延長された競技時間の間も再起動試験対策を続けることを決めます。

17:30頃

再起動を繰り返すとアプリケーションでconnection refusedが出ることが発覚します。
これの対策としてDB接続ができるまで待機する処理をアプリケーションに入れましたが、直りません。
getTrendWorkerがDBの起動までconnection refusedをを吐き続けていることがわかります。
しかし、今度はアプリケーションの起動まで1分程度かかることがわかり、運営が1分も待ってくれるのか？という話になります。
結局競技時間終了までアプリケーションの起動まで1分もかかる理由はわからず、終了します。

翌日

再起動試験は通り、無事予選突破できました。

運営から聞いた話いろいろ

今回のISUCONの問題作成にはtraPのメンバーがいたため、(当然守秘義務などの観点で問題ない範囲で)裏話を聞くことができました。

再起動試験落ちかけたらしい

再起動試験にかなりの時間をかけていたのですが、実は再起動試験に落ちかけていたらしいです…

落ちそうになった理由は競技中の再起動試験で一切目を向けていなかったサーバー3^[1]です。
サーバー3のdisk使用率が100%となっており、isucon-env-checkerが走らない状態となっていたらしいです。
このため失格になりかけていたらしいのですが、

この作業は全サーバーで実行する必要はありません

との記述があり、サーバー3以外では問題なくisucon-env-checkerが動いたため失格を回避できたそうです。

原因は改善の中で入れたgetTrendのworkerです。
複数台構成がうまくいかなかったのはDBとの接続がうまくいかなかったためなのですが、
getTrendのworkerは接続がうまくいくいかないに関わらず走り続けるようになっていました。
このため接続失敗のエラーを0.5sごとにエラーを吐き続け、isucon-env-checkerを走らせた時にはdiskがログで埋まっていたようです。

感想

非常に勉強になり、また点数も綺麗にはねて競技性もある非常に良い問題を作ってくださった運営の方々、本当にありがとうございました。
本戦までに一般枠で通過したチームとも渡り合えるように精進したいと思います。