ISUCON14に参加してきました

初期点 (1022)

初期点は 1022 でした。

自分が配布された Cloudformation の Security Group にアウトバウンドの設定がないことに気づかず、用意していた pprotein.sor4chi.com に pprotein-agent の集計結果が送信できずつまづき、結局サーバー内にpproteinを立ててLocalForwardするという力技で解決しました。
この時点で開始から42分ほど経過していて申し訳ない…。

Index 貼り (3004)

@a01sa01to が Index をガンガン貼って行ってくれました。
自分が pprotein を調整している間、Slow Query Logは既に出せていたので、セットアップが終わった瞬間に計測してスコアUPというなんとも素晴らしい初動でした。

自分が見た時にはもう Slow Query Log で見つけられる Index の貼り忘れはほぼない状態でした。

appGetNearbyChairs の高速化 (3408)

@Ryoga_exe が appGetNearbyChairs が条件の評価順を変えれば早期リターンできることに気づき、高速化してくれました。

chairAuthMiddleware の 高速化 (4225)

この時点で、pprof では chairAuthMiddleware 直下の GetContext が大部分を占めていました。
@sor4chi が accessToken から引ける chair のオンメモリキャッシュをし、Middleware 上で DB へクエリする回数が減りスコアが上がりました。

RetryAfterMs を 500ms に (6940)

ここを見つけるまで1時間以上詰まりました。

明らかに Notification 系のエンドポイントの呼び出し回数と、それに基づく Access Log の Sum Time が多いことに気づき、実装を見ると、RetryAfterMs が 30ms に設定されていました。
(仕様書にも書いてたらしいのですが、メンバー誰も見当をつけておらず偶然の発見となってしまいました…)
@sor4chi が RetryAfterMs を 500ms に変更すると、トランザクションの占有時間が減り他がリクエストを多く捌けるようになったのか、スコアが上がりました。

椅子マッチングを貪欲に (13073)

@a01sa01to が 椅子マッチングが効率の悪い乱択実装になっているのを見つけ、貪欲にマッチングさせる方向で実装することで高速・より良いマッチになりました。
なんとこのチーム、3人とも Atcoder Heuristic 青コーダー なんですよ。まあISUCONの8時間で最適化を実装する余地なんてないわけですが。
@a01sa01to がしきりに「Flow流せるんじゃね？GoのACLにFlowないかな」とか呟いてて面白かったです。

この頃、他のチームのベンチ状況で1 位になる瞬間があり、上位を走れていたんじゃないかなと思います。

getLatestRideStatus 関連の N+1 解消 (14674)

@sor4chi が getLatestRideStatus関連 の N+1 問題を解消しました。

沈黙の時間

この間3時間、ほとんど何もできないままでした。
@a01sa01to はサーバー分割をトライするも WARN が出まくって0点になったりスコアが下がってしまったり。
@sor4chi は chairPostCoordinate の高速化に挑戦するも整合性エラーで落ちまくり…。
苦しい時間でした。
@Ryoga_exe は頑張って N+1 を潰しまくってくれたもののスコアにはほぼ反映されず…。

メトリクス的にも chairPostCoordinate が大きく影響していることがわかっていながら、全く手を付けられなかったのが辛かったです。

途中で No space left on device が出て、「あーこれ Docker でよく見るやつー」と思いつつ df -h で確認すると pprotein 内の *.log と *.pb.gz、mysql-slow.log がディスクの殆どを占有していました。
後でログを見返せなくなるのは残念ですが全て削除して対処しました。

ownerGetSales の N+1 解消 (15191)

@Ryoga_exe が ownerGetSales の N+1 問題を解消しました。

isu テーブルの現在位置所持 (15343)

@a01sa01to が isu テーブルに現在位置を持たせることで、appGetNearbyChairs が高速化しました。

この後で @Ryoga_exe や @sor4chi が残りの簡単な N+1 問題を解消しました（スコアは上がりませんでしたが今後に効いてくることを期待して勇気のマージをしました）

ISUCON_MATCHING_INTERVALのチューニング (16890)

@a01sa01to がヒューリスティックを頑張ってくれました。
internalGetMatchingの重みや閾値を調整したり、ISUCON_MATCHING_INTERVAL を 2.0 まで上げることで負荷を下げて、スコアを上げてくれました。

ログ閉じ (23656)

ISUCONではそこそこの追試落ちが発生するため、安定をとって残り15分になったら何がなんでも締め作業に入ると言っていました。
時間になったので @sor4chi が計測に使っていた nginx, mysql のログ出力をやめ、pproteinを剥がして計測をしました。するとなんとびっくり、スコアが 23656 になりました。ログ閉じただけでこんなに伸びたのは初めてなので結構衝撃でした。

例の InterpolateParams=true 設定もここでしています。

MySQL の秘伝のタレを導入 (27491)

最後に @sor4chi が MySQL の秘伝のタレを導入しました。去年用意してたやつで、バイナリログを無効化したり、バッファプールサイズを増やしたり色々やっています。

再起動して試験 (24640)

最後に再起動して envcheck してもろもろの最終確認をしてベンチをもう一度回して終わりです。

競技内の最後のスコアがそのまま使われるのを知らなくて、残り時間がもう少しあったのでベンチマークをして27000代まで戻せばよかったと後悔しています。
25 位スコアは出ていたのに…