ISUCON 7 準優勝で、やったことまとめ
ISUCON 7 本戦、残念ながら勝てず、準優勝に終わりました。スコアや順位はともかく、やろうと思っていたけど出来なかったことが多くあったので、やはり難しいなと思いました。
運営ならびに参加者のみなさん、お疲れ様でした。
今回の問題はクッキクリッカー。APIが「クリックによる椅子追加」や「アイテム(生産設備)の購入」などを送ってくる。さらに WebSocket で接続していて、複数プレイヤーがゲームを共有している。APIに操作予定時刻が含まれていて、その時刻までは操作コマンドはゲームスコアには反映されず、なおかつその操作履歴を各プレイヤーに送る必要がある（他のプレイヤーの操作をアプリ側で表示するため）。
未来の操作予定時刻が入っている、というのが良いポイントでした。複数のプレイヤーで同じゲームを共有している場合、他人の操作を表示したり、ゲーム内容の整合性をとるために、時刻が入っている、というのはよくあるパターンだと思います。これによって、受信したコマンドを単純に処理すること（今回であれば、椅子数をただインクリメントするなど）が出来ないので、問題としても面白かったです。
さて、やったことの記録をざっくりと。
まず soundTricker さんが、環境まわり。全員のSSHキーを全サーバに登録、systemdをGo実装に切り替え、アプリをgitにPushなど。
その後、全員でアプリのコード読みながら、重そうな箇所など話し合い。
計測を待っている時間はないので、見た感じでできそうなところは taxpon さんに開始してもらう。najeira と soundTricker さんはベンチマークをかけて計測などに取り掛かる。
最初のスコアは 9,000 くらいで、DBサーバで少しwaitがありつつ、基本はアプリのCPU負荷、ネットワークは問題ないということが分かった。MySQLのほうで見るとロックと room_time に時間を使っていた。
taxpon: アイテムは変更無いので、グローバル変数にハードコーディング。
najeira: 複数のクライアントのために、それぞれ getStatus が走っているのが無駄なので、キャッシュ化。
ロックをとって、あるクライアントが getStatus を計算している間は他を待たせる。計算が終わればロックが解除され、なおかつ新しいキャッシュがあるのでそれを使うことができる。addIsu, buyItem した場合は内容が更新されているのでキャッシュは見ずに強制更新。
getStatus を処理するのは単一のクライアント(goroutine)だが、他のクライアントもそれが終わるのを待っており、待ち時間はあまり短くならなかったが、CPUが空いたはず……？ ロックによって同じルームの getStatus が直列になってしまうのは気になったが、スコアがあがったのでとりあえずマージ。
バックグラウンドの goroutine を起動してgetStatusを更新させ続けて、各クライアントから最新のキャッシュを使うようにしようと思ったが、この時点では後回しの判断（そして、結局手はつけなかった）
また、キャッシュの効率をあげるために、同じルームの場合は同じサーバにつながるように、部屋名からサーバを決定するロジックを追加した。最初、グローバルIPを返していたが、ドキュメントを読み返してFQDNのほうがよいとあったので修正。
この変更で 16,083 点。
taxpon: addings の登録で、同時刻のものがある場合に加算するためにロックしていたが、どうせあとで集計するから、別レコードとしてINSERTすればいいよね、となったので別テーブル addings2 を作って単純INSERTする方式を実装開始。
最初の実装はバグがあってバリデーションが通らず、3人でかなり悩んだ。最終的には soundTricker さんに引き継いでバグ修正してもらった。
スコアには大きくでなかったが、DBサーバのwaitが減ったので良しとしてマージ。
他のボトルネックが手前にあると、効くはずの改善がスコアに反映されない。しかし、あとで手前のボトルネックが解消されたときに一気に効いてくる。なのでスコアが下がっていなければとりあえずマージする方針でやっていた。
soundTricker: addings2 をキャッシュ化。再起動があるのでデータベースへの INSERT や UPDATE は実行しつつ、オンメモリにも持っておくことで、SELECT を削減。
その後、DBサーバは余裕があって、基本CPUバウンドだったので、DBサーバもアプリとして対象に追加して4台アプリ。これで2万点を超えるようになった。
najeira: 時間を計測する処理をアプリに埋め込んで、どのあたりが重いかを計測。addIsu や buyItem よりも、calcStatus が重くなっていることが分かった。
この計測には https://github.com/najeira/measure を使った。WebSocketだったのもあり、アクセスログからの集計ができなかったので、各関数の先頭に計測用のコードを入れた。
func addIsu(roomName string, reqIsu *big.Int, reqTime int64) bool {
defer measure.Start("addIsu").Stop()
...
deferで関数を抜ける時にタイマーを Stop できるので Go はいいね！
さらに計測結果を出力するハンドラを追加（あと /initialize で measure.Reset() するくらい）。
r.HandleFunc("/measure", measure.HandleStats)
これで /measure にアクセスすると、計測結果がCSVで出るので、Googleスプレッドシートに貼っていた。以下のような感じ。
getStatus が遅いのはキャッシュのロック待ちなので、そこもなんとかすべきだったが、getStatusの中でやっている calcStatus を速くすれば解決するかもということで、ループで計算しているところの改善に着手。1000回ループの箇所で、イベントが発生した時刻だけループを回せばよいので修正してみたが、バグのためバリデーションを通すことができず、時間内に出来ないと思ったのでペンディング。
ミドル周りを確認。ただ、ミドルまわりはとくに問題がなかったので、何もやることはなかった。
soundTricker: やはり calcStatus を改善したいということで、引き継いで取り掛かってもらう。途中からペアプロ的な感じでバグ探ししながらやるも、最後まで完全にバグを取ることはできなかった。
この間 taxpon さんには地道にキャッシュ化を進めてもらい buying と room_time もキャッシュするようにした。また、良いスコアが出るまでベンチマークを繰り返してもらっていた。部屋ごとにサーバを分けるロジックが賢くなくて、バラつきがあったので、ベンチマークごとにかなりスコアが変動していたため。
部屋を決めるAPIを1台で受けて、単純にラウンドロビンすればよかった（あとで聞いたら fujiwara さんチームはそうしていたらしい）。
addings2, buying, room_time のキャッシュ化は、そこまで大きくスコアには効かなかった印象（細かいスコアのメモは残っていないけど）。おそらく、 getStatus(calcStatus)がボトルネックになっていたため。
最終スコアは 28,117 ということで、ぎりぎり準優勝ということになりました。
まとめ:
- mItems をハードコーディング
- getStatus(calcStatus) の結果をキャッシュ
- addings2 を作って、FOR UPDATE のロック回避
- addings2, buyings, room_time をキャッシュしてSELECT削減
- calcStatus の改善は間に合わず
反省点としては、ボトルネックの調査が甘かったこと。サーバ単位やメソッド単位では計測していたが、ちゃんと pprof もやるべきだった。big.Int で事前計算できる箇所がたくさんあったのに、後回しにしてしまったことでスコアを伸ばせなかった。また、試合後にPython実装を見たら簡単だったので、Pythonを選んでもよかったかもしれない（メンバーは3人ともPythonista）。
ISUCON運営のみなさま、ありがとうございました。
写真: USBモニターを全員で用意して準備万端(bluerabittさん、soundTrickerさん、ありがとう)。
自分はマウスパッドも持ってきている図。
なお、となりは強豪 fujiwara 組でした。
この記事はQiitaの記事をエクスポートしたものです
Discussion