ISUCON11予選に参加しました

TL; DR

ISUCON11予選にチーム「わかんないッスー!!!」として参加しました。
使用言語はRubyで主催側追試通過時の最終得点は29766点。
大きい修正を突っ込む方向に舵を切れなかったのと、場当たり的な対応の多さとその精度の悪さが目立ったと感じています。

当日使用していたリポジトリはこいつです。

github.com

事前準備

前職の同期を誘っていたのですが反応が芳しくなかったためソロ参加を決意。
そのため事前に秘伝のタレ/デプロイ方法/必要パッケージのインストールを自動化しようと考えていました。
ISUCONに参加するにあたって、秘伝のタレ用の勉強の他に新しいこと覚えようとansibleを使い倒すことに決めました。

余談なのですがISUCON練習環境構築にAWS CDKも覚えました。
CFnの方が好きだなぁってなりましたが。

結果として出来上がったのがこれになります。

github.com

基本的に反映のオペミスが存在しない点とデプロイ後の設定永続化忘れを考える必要がない点、複数台への反映を全く考えなくて良い点はかなり助かりました。
ただ正直deploy周りまでansibleで解決する必要はなかったのと、ssh越しにコマンド叩くことが多くてそこが少し微妙だったと感じています。
事前の練習でも何度か使って慣らしていたんですが、本番はスピード感が違っていてデプロイ待ち時間がちょっと勿体なく感じました。

当日

07:00

  • 起床
  • 朝食として完全無欠コーヒーを飲む

07:30

  • 急に思い立ってnginxでhttp3やってみるかと環境構築開始
    • ISUCON想定でubuntu20.04環境をt2.microで用意
  • 適当にビルド走らせてたらCPUクレジット食い切ったので断念

09:00

  • リングフィットアドベンチャーで一汗かいてシャワーへ
  • 業務開始前にもやるようにしてるんですが午前のパフォーマンスがめっちゃ変わりますね

09:40

  • YouTubeでISUCON予選ライブ中継を見始める
    • IOTってことはINSERT過多になりそうだなぁ
    • 分析系の重いクエリありそうだなぁとか考えてた

10:00

この時間帯は当日マニュアルの確認をしながらプロファイリングツール導入とかやってました。スタートダッシュは上手だった。
マニュアルは流し読みでコンディション反映周りとスコア計算についてを手元のnuboardにメモしてました。
あとはログ出力設定と一緒にMySQL5.7用の秘伝のタレも投入してます。

  • 10:03: CFnテンプレート持ってくる
    • c5.largeってことはCPU: 2core, Memory: 4GBのネットワーク帯域幅10Gbpsかぁ
    • EBS: 20GBだけどここのクレジットがネックになるような問題にはしないだろうなぁとか考えてた
  • 10:06: CFn流しながらREADMEに当日マニュアル等のURLを追記
  • 10:06: サーバが立ち上がったので情報を取得
  • 10:13: <6659> Rubyへの変更と必要なもの入れて初期ベンチ
  • 10:20: nginx, mariadbのconf, webapp等必要なものをgit管理下に追加
    • Ubuntu20.04ってaptでmysql入れると8.0になるからなぁと思いmariadb採用に納得してた
  • 10:43: <3012> 各ログ出力設定とNewRelic, stackprofを導入
  • 10:48: alp設定を今回用に修正
    • これが終盤までバグっててcondtionとiconが一緒くたになってた
  • 10:56: puma用のconfigを追加

11:00

この辺りはnginxと格闘してた時間帯でした。細かい設定をワンパンで終わらせられなくて失敗/やり直しをめっちゃやっててアホかと。
カーネルの秘伝のタレもここで入れてます。

  • 11:04: gzip_static用にassetsをgzip圧縮してgit管理に
  • 11:13: nginx用の秘伝のタレ投入
  • 11:22: nginx <-> puma間をsocket接続に変更
  • 11:28: <5010> ベンチ実行
  • 11:49: /registerとか/isuとかをnginxから返すように

12:00

nginxの修正を一旦諦めてapplication側に手をつけ始めた時間帯です。
こいつnginxの設定が下手すぎる。

  • 12:16: <4472> 余計な設定入れたり消したりしてベンチ通るところまで戻した
  • 12:21: isu.jia_isu_uuidとjia_user_idにindexを追加
  • 12:21: INSERTのLOAD DATA LOCAL INFILEへの変更対応着手

13:00

/api/conditionのPOSTへの対応をやっていた時間帯です。
isu_conditionのPK変更対応は素晴らしかったなと思っています。

  • 13:13: POST /api/conditionのINSERTを削除してtmpfsにCSV形式で出力するように
  • 13:13: /dev/shm書き込みになるので面倒だと思いAppArmor削除
  • 13:14: isu_conditionのPKをjia_isu_uuid, timestampに変更しidからAUTO_INCREMENTを削除
  • 13:49: 吐き出したCSVからLOAD DATA LOCAL INFILEでDBに毎秒insertするbot作成
    • ここで毎秒に設定したことを競技終了まで忘却します
    • 終わった後でこの設定を短くすることを考えついて悔しい
  • 13:58: <5854> ベンチマーク実行

14:00

PK変更と遅延書き込みでDB的にはisu_conditionが怖くなくなったので次にやばそうなAPI修正に着手し始めた時間帯です。

  • 14:00: valid_condition_format?を固定値で判定してbooleanを返すように変更
  • 14:03: <7078> ベンチマーク実行
    • この実行のタイミングからDBに余裕が出てきているのを確認
  • 14:05: drop_probabilityを0.5に変更
  • 14:16: INSERTの代わりに作成していたCSVをbotが使用後に消すように変更
    • 手動で実行するようにしたら後半1秒越えするようになっていたので
    • mysql実行とrmの間にどうしても書き込まれた値を取りこぼしてしまうので
      今思えばmvとかでatomicに名前変えた後にそのファイルを使った方が良かった
    • これでDB負荷よりapplication負荷の方がキツいことを確認
  • 14:18: 複数台対応のためconfig類を修正
  • 14:27: <4866> WEB+APP1台, DB1台構成でベンチマーク実行
    • フロント側で詰まっててDBが余裕(CPU使用率3割くらい)なのを確認
    • ああこれはapplicationのCPUをなんとかする問題なんだなと思い始める
    • 前述ですがこの認識で最後までいったのがダメでした
  • 14:35: 3台目を追加してnginxの重みづけを調整しDBサーバにもAPIリクエストを流すように
    • これが最高に頭悪かったです
    • DBサーバにAPIリクエスト捌かせないようにしていればまた結果変わった気がしています
  • 14:37: DBは余裕あるのでdrop_probabilityに0を設定
  • 14:40: nginxの生アクセスログを引っこ抜いてくる
  • 14:44: <9802> ベンチマーク実行

15:00

この辺りから/api/trendの負荷が目立ち始めていたのでそれの修正をしてた時間帯です。
どんどん対応の雑さとかが露呈して来ていてコミットログ読み返しながら頭抱えてます。

  • 15:05: service_urlをキャッシュするように変更
  • 15:09: <7397> ベンチマーク実行
  • 15:23: <3407> /api/condtionのPOST内のjia_isu_uuidの存在チェックにSELECT 1を使うように
  • 15:30: /api/trendでisuを全取得するように変更
  • 15:32: revert
  • 15:42: 性格が固定値なのでアプリ側に定数として持つように
  • 15:56: ORDER BY timestamp DESCをMAX(timestamp)を使ったサブクエリに書き換え
    • 降順のtimestampって要するに最新が欲しいんだろ？って書き換えました
    • メインクエリはPK参照になるので高速
    • サブクエリ部分はindexすら使わないのでこれ思いついたのは偉かったです
    • Select tables optimized awayになる
  • 15:58: <11296> ベンチマーク実行

16:00

この辺からgraphとの格闘が始まってます。
あとnginxの重みを変更してなんとかしようとしたログとか今更alp直してるログが残っててお前アホかと思いました。

  • 16:03: isuのindexを(jia_isu_uuid, jia_user_id)に変更
  • 16:03: graphのCOUNT(*)をSELECT 1に変更
  • 16:06: <11660> ベンチマーク実行
  • 16:24: GET /api/conditionが重めなのでORDER BY DESCを削除しアプリ側でreverse!するように
  • 16:27: <11870> ベンチマーク実行
  • 16:30: ようやくalpの正規表現がおかしいことに気づいて直す
  • 16:38: conditions_countの計算部分を定数と比較するように変更
  • 16:42: <11117> ベンチマーク実行
  • 16:42: alpのconfigがまだおかしかったのを直す
  • 16:48: sitting_countの計算をrubyのcountを使うようにした
  • 16:51: <13660> ベンチマーク実行
  • 16:52: user確認のCOUNT(*)を潰し
  • 16:53: icon返却部分のSELECTをindex効くように変更

17:00

ちゃんとISUCON的な考えで点数をガバっと上げられたのが気持ちよかったんですが、直後にアホになった時間帯です。
Don't guess, measureが守られてなさすぎて笑えないです。

  • 17:03: <13156> ベンチマーク実行
  • 17:08: generate_isu_graph_response初っ端のクエリをtimestampで1日分取得するように絞る
    • application側のCPUがボトルネックだったのは把握していたので処理するデータ量減らせないかの苦肉の策でした
    • お前1日分って言ってるんだから1日分持って来いよって言いながら修正入れました
  • 17:11: <19901> ベンチマーク実行
    • ここからCPU負荷削ったからnginxに戻るぞって判断をしていましたが今考えても意味わからん
    • 前述の通りなんですがアプリケーションのCPU負荷を削ったらその分DBに来るんですよね
  • 17:15: この辺りでポータルが死ぬ
    • 運営の皆さんお疲れ様です。
  • 17:25: ログを止める
  • 17:26: 再起動対策にStartLimitBurst=999を設定
  • 17:31: ここからアプリ変更する力ないなと思いnginxを弄り始める

18:00

nginxの調整を一生続けてた時間帯ですね。未来から来たんですがそれ意味なかったよ。

  • 18:10: <15425> ベンチマーク実行
  • 18:13: <28904> NewRelic切れてないことに気づいてストップ
  • 18:18: <30641> DBサーバ向きのアクセスを減らすようにnginxのweightを調整
  • 18:22: <22359> さらにweightを調整
  • 18:36: <28631> least_connに変更
  • 18:39: <24082> 30641出てるパラメータに戻した
  • 18:45: 競技終了
  • 18:48: botのDB書き込み間隔を短くすることで点数上がるかもしれないことを思い出す

反省点

一つ一つの対応が全て中途半端に終わっていて雑だったのが一番の問題だなと思います。

特にDon't guess, measureが徹底できていないのと、目に見えるボトルネックを表面上ちょっと早くして完全に潰し切れてない段階で次に進もうとしていたのがコミットログからも読み取れました。
後者に関してはボトルネックが移ったことを確認して次の修正箇所を決めて実装するってイテレーションを高速で回せるならまだ考えもんなんですが。

この辺の改善/確認を高速に回すには、とにかく優先度付けと形にする実装力が足りてないかな。

あと無限にnginxを擦るな。

感想

あー悔しい、来年こそは。