isucon8本戦に参加してきた
昨年に引き続きISUCON予選を突破した。去年はたまたま出場できた感が強かったけど、今回は結果的に学生枠２位で通ったのでちょっと自信は芽生えた。
ISUCONでの自分の役割はアプリケーション(Go)。去年は本当にコード書くしかできなかったけど、過去問を解きまくったのでデータベースも基本的な知識はついて全面的にロジックの改修はできるようになった。
競技開始まで
前日の新幹線の運行停止に巻き込まれたりしたものの、無事東京に到着して起床も成功。
開場前に会場に到着していい席を確保したあとは、Wi-Fiの設定したりリポジトリ作成したりKMCから同じく参加した別チームと談笑するなどして時間を潰した。
isuconやっていき pic.twitter.com/2DXbXTs8tE
— nakario (@nakario_jp) 2018年10月20日
準備も万端で時間の余裕もあり緊張がほぐれてきたくらいで競技開始時間。
去年も思ったけどISUCONはオープニングがすごく凝っててモチベめっちゃあがった。
問題の詳細は公式参照。
競技中のログ
開始〜11時：Dockerの操作に慣れておらずアクセスログやスロークエリログ、フレームグラフの生成にとまどる。
チームメイトのmurataがコンテナに入って無理やりフレームグラフを取ってくれたのでそれを確認。
GET /infoが処理時間の大半を占めているため、ここを調査。
よく読まなくても無駄にtradeを取ってきているのがわかったので、LIMIT 1を追加したら一気に5000点を突破して一位に躍り出た(数百点差で別の学生チームがいたので単にガチャに勝ったっぽい)。ここが当日のハイライト。
11時〜13時：Dockerに阻まれて色々データが取れないのでどこがネックになっているのか把握できず、とりあえずフレームグラフからログイン処理内の暗号化が重いようなのでTODOに書かれているBAN機能を実装することに。
(たぶんこの時点でCPU使用率が90%切ってたはずで、アプリケーションがネックでないので判断ミス)
実装できたもののスコア改善せず。
13時〜16時：この頃にはmurataとaokabiがDocker全排除に成功していたのでスロークエリログを確認すると、ローソク足の生成のための集計に時間がかかってるようだったので、別テーブルに予め計算結果を保存しておくことに。ここもCPUネック処理なので判断ミス。
明らかに遅そうなSQLだったのと解決策をサクッと思いついてしまったので食いついてしまった(その割に実装に時間がかかったのはcreated_atとSTR_TO_DATE(DATE_FORMAT(created_at, '%Y-%m-%d %H:%i:%s'), '%Y-%m-%d %H:%i:%s')の違いで一秒ズレたりズレなかったりするバグの解決に時間がかかったから)。
16時〜18時：htopを見てCPUネックじゃないことに気づく。過去の経験からデータベースのロックだと決めつけてしまった(判断ミス)。スロークエリログにも総ロック時間がとても長いクエリがあったため競技終了まで勘違いに気づけなかった。
その問題のロックが長いクエリというのが椅子のトレード関連のもので、トレードのロジックがめちゃ難しかったので途方に暮れている間に競技終了。雑にN+1を解消しようともしたけどバグが治りきらなかった。
反省点
- もろもろの計測環境が整う前に方針を決めてしまってるのでかなり時間を無駄にしている。特別賞に目が眩んだというのはある。
- 計測環境が整ってからも全体の情報を見ていないため、一つのソースから間違った判断をし続けてしまった。
- レギュレーション(仕様書)の読み込みが甘い。バルク送信は完全に気づいてなかった。ログの欠損のエラーが出たときもトレードに時間がかかりすぎているのが原因と(何故か)思い込んでた。
- チームメンバーが詰まってたり非効率的なことをしてそうな時の声かけが(去年よりはできてたものの)足りなかった。
SNSシェア機能には気づいていたものの、ALL or NOTHINGだと思ってたので10%だけ有効化するみたいなのはどっちみち思いつかなかったと思う。これは反省というよりも普段からABテストみたいな経験を積んでるかどうかの違いかと。
感想
去年に比べて成長しているものの、まだまだできることがあるなぁというのが大きい。ISUCONは奥が深い……。
学生なので交通費＋宿泊費もでるし昼夜のご飯も食べられるし、マジで最高のイベント。
運営＆協賛の皆様、お疲れ様でした＆ありがとうございました！
ISUCON7本戦に学生枠で参加してきた & こうしていれば優勝できたかもしれない方法
経緯
なんとなくで参加を決め、なんとなくでメンバー(@aokabit, @murata)を組み、なんとなく過去の予選問題を解いたりしていったところ、予選直前に解いたPixiv社内ISUCONにおける経験を活かし*1Cache-Control: publicをつけたところ、マシンを１台しか使用していないにも関わらず学生枠で予選突破できたので非常にラッキーでした。
isucon本戦出場決定したの嬉しすぎてサイゼで「やったーーー！！！」って叫んでしまった
— nakario (@nakario_jp) 2017年10月22日
本戦でやったこと
とりあえずNewRelicを入れたりgo-torchからFlameGraphを生成したりしてgetStatusがネックなのはひと目でわかりました。
中でもBigIntの掛け算が大きな割合を占めているので、雑にそれらを眺めてみたところ、new(big.Int).Mul(str2big(hoge), big.NewInt(1000))しているところが目立ったので、big.NewInt(1000)を使い回したり文字列の最後に+"000"した後str2bigで代用したりしたものの、あまり効果が出ず。他の掛け算は色々な場所に散らばっていて共通部分を見いだせず、なかなか取っ掛かりが見いだせないでいました。
@murata が同じくgetStatusで大きな時間を消費しているbig2expをやっつけてくれるらしいので、賭けに出てgetStatus全体をキャッシュしてみることに。
キャッシュにはgolang.org/x/sync/singleflightを使用しました。何も考えずにroomNameをキーにしてgroup.Doでラップしたところ、ドカンと並列数が上がってこれはいけるか！！？と期待したもののベンチマーク後の検証に失敗。流石にこうも簡単ではないかと思いつつもこの方針ですすめることに。
コードを眺めていると検証に失敗しているのはaddIsu、buyItemしているにも関わらずキャッシュを利用しているせいであることはすぐに判明しました。そこでそれらの直後にgroup.Forgetを仕込みキャッシュをクリアしたところ、スコアはもとに戻ってしまいました。ログを吐かせて確認したところgetStatusの呼び出しはほとんどがaddIsu、buyItemの後に行われているもので、serveGameConnの始めや500ミリ秒周期で現在のゲーム状況を送信する箇所での呼び出しは割合として低いものだったようです。
同期地獄
こういった状況を踏まえてsingleflightによるキャッシュを効かせるためにはaddIsu、buyItemの変更が加わった状態で複数GoルーチンでgetStatusの呼び出しを同時に行う必要があります。しかし、恥ずかしいことに、チーム内で１番Goに詳しいことを自負していながら、数が減ったり増えたりする複数のGoルーチンを同期させる方法を知りませんでした。今考えてみると知らないなりに色々やり方はあったと思いますが、競技中は焦りやらプレッシャーやら*2で全くアイデアが浮かんでこず、思いついた！と思っても負荷走行後のバリデーションに失敗し*3、適当にネットで検索してライブラリを見つけたものの本番で使ったことのないライブラリに手を出す恐怖から試しもせず*4、最終的に辿り着いたのがこのコードです*5。
for {
if time.Now().UnixNano() / int64(100 * time.Millisecond) / int64(time.Nanosecond) % 5 == 1 {
break
}
time.Sleep(100 * time.Millisecond)
}
何をしているのかというと、現在時刻を100ミリ秒単位で数えて、その数字を5で割った余りが1の場合ループを脱出し、そうでない場合100ミリ秒スリープしてループする、という超原始的な同期を行っています。何時間もかけて最終的に出てきたのがこれって……。
しかしこの変更により3000近く*6だったスコアが初めて一万点を超え、競技終了時間も迫っていたので最終的にこれをベースに複数台に分散した実装で提出。ちなみに最終スコアは7248で一台のほうがスコアが良いという残念な結果に。書きながら思い至ったのですが3台のアプリサーバと1台のDBサーバでこれを行うとDBのロックタイミングまでもが同期されてスコアが悪くなるのは当然ですね……。
複数Goルーチンを同期させる方法の正解(?)
syncパッケージのCondに生えているBroadcastを使用します。
詳細はこちらにあります。
簡単に説明すると、各roomごとにGoルーチンを起動して、time.NewTickerによって定期的にcond.Broadcastを呼び出し、cond.Waitで待機していたgetStatusWithGroupを複数同時に起動します。この関数はsingleflightのgroup.DoでgetStatus関数をラップしただけのもので、複数同時の呼び出しを一回の計算のみで処理できます。
この変更を再現環境*7にて検証したところ、初期実装の4000~6000点から14000~16000点まで跳ね上がりました。本番環境で一台で動かしたときの初期実装が4000点前後だったことを考えると、4台全て使えば優勝も狙えたので非常に悔しいです。
まとめ
標準パッケージの型ひとつ知っているだけで出来ることが大きく変わるので、普段から色々なコードを書くことで勉強することが大事だと思いました。あと本番はめっちゃ緊張するので精神力も大事ですね。お寺とかで修行を積んで出直します。
