窓を作っては壊していた人のブログ

この謎のブログタイトルの由来を知るものはもういないだろう

ISUCON12予選にソロ参戦して敗退しました

今年も相変わらず一人でISUCONに参戦しました

ISUCON11予選にソロ参戦して敗退しました - 窓を作っては壊していた人のブログ

昨年も一人で参加したのですが、意外と戦えるのではという謎の自信が生まれたため今年も一人での参加を決意し参加しました。

得点としては 6501 点で 698 チーム中 150 位という結果でした(適当なQuerySelectorでやったから違うかも、参考値程度に)。

追記: 2022-07-25 17:00ぐらいに実際にスコア遷移どうだったかが見えるようになったのでそれに合わせてスコアの箇所を編集しました。

isuconスコア変遷

去年とのDiff

昨年は Golang を使って競技に挑みましたが、今年は例えば Node.js とか普段使っているような言語で腕試しできないかなということで Node.js で参加しました。 普段使っている言語なので、例えばアプリケーション側で何か施策を試したくなった時にスムーズに書けるだろうという自信がある程度のこの決定を後押ししました。

変えてみて実際思ったのは、思っていたとおり初期スコアは低い、そもそも何使ってプロファイリングすればいいんだとなり、意外と苦労しました。 とは言え試したい施策を慣れていない言語のコーディングの遅さで試せないよりはマシという判断で突き進んだのは悪くなかったかなと思います。

やったこと

github.com

今年も何かやった毎にスコアメモみたいのが出来なくて、何をしてうまく行ったのかが振り返りできませんでした。 これは来年頑張りましょうですね(去年もそうだったのに成長していない)。 時系列でやったことをメモっておこう。

複数台構成の練習をしていなかったので、今年も相変わらず1台のみを使用して戦う感じになりました。

git管理

アプリケーションの管理と mysql の設定、また nginx の設定の管理をしました。 mysql の設定毎回これはハードリンクだっけ、シンボリックリンクと悩んだりしている気がします。 今年はハードリンクだったはず!で試したものの、なぜか slow query log が出力されず、なんで!?と悩んである間に2時間が経過していました(アホ

ベンチ前後のDBのレコード数推移の観察

ベンチ回すついでにどのあたりに INSERT が走るかの確認をしました。

https://github.com/yamachu/isucon12-qualify/issues/4#issuecomment-1193044476

最初っから visit_history レコード多くね???と困惑しながらベンチを回してみると、数百ちょいレコードが増えるみたいなのが観測されました。 全体総数の中から見れば1%の増加にも満たないですが、総数がちょっと多いのでここは改善できる箇所だなとある程度あたりをその時につけていました。

この時点でスコアが2398。

visit_history テーブルにINDEXを貼る

slow queryが2時間かけて出るようになったので、再度ベンチを回して眺めます。

https://github.com/yamachu/isucon12-qualify/issues/4#issuecomment-1193054428

激遅ではないが、回数と総時間が長い visit_history テーブルへのアクセスは改善の余地があるなとこれで確信に変わりました。 また同時に top コマンドで眺めていたら mysql の CPU 使用率が高い、node はそこまで、そしてメモリは余りまくってる、みたいな状況を確認。

ってところで、今回はまずは mysqlボトルネックを下げて、他のボトルネックが出てくるからそれを順番に倒せということね、理解みたいな勝手な判断をしてINDEXを足していきます。

今までの(?)問題だと、/initialize 時にDBをまっさらにして初期データを入れる感じの構成だったので、schema.sqlを書き換えればいいか〜と進めていたのですが、ベンチ回してもどうも傾向が変わらない、なぜ!?みたいになりまた時間を溶かすやつをしていました。

自分で適当にmigrationのクエリを流し込むしかないのねに気づいてからは

こんな感じでDB再起動の時に一度migrationをかける · yamachu/isucon12-qualify@97a5f7b · GitHub

DBのリスタート時にmigrationをかけるような構成にしました。

それで再度ベンチを回すと100点程度上がった気がします。

https://github.com/yamachu/isucon12-qualify/issues/4#issuecomment-1193054458

クエリ回数が増えてその分スコアが上がったんでしょう(多分 2447点

今で12:50

visit_historyの軽量化

INDEXを足したものの、ちょっぱやになったかと言うとそこまで早くなっていません。 explainで実行計画を見てみると、group byが走ってかつMINが走るので、using temporaryになっています。 MINなんてもう固定で見つけろよ!!!とキレながら他の参照箇所を見てみると特になくて、じゃあこれMINのやつだけ入れればいいじゃんに気が付きます。

ってことでやったのが以下

これでquery早いのでは · yamachu/isucon12-qualify@c9b5fe5 · GitHub

やったこととしては

  1. visit_history_min テーブルを生やす
  2. migration時に初期データのMINを事前にクエリして、そのテーブルに突っ込む
  3. 新規で入るデータは INSERT IGNORE INTO で min テーブルに突っ込む
  4. select する時はminテーブルに対して

これで行けると思ってベンチを回したところ、mysqlへの負荷が一気に下がって変わりにNodeの負荷が高まりました。 そしてスコアは下がる…2096点。 ボトルネックが完全に移ったと見て正しい施策…のはずと踏んでrevertせずに進みました。

https://github.com/yamachu/isucon12-qualify/issues/4#issuecomment-1193060020

ここで 14:00

sqliteとの出会い、そしてログ出力

そう言えばこれで終わりじゃないよね…と思いファイル類を見てみると 数字.db のファイルが大量に… なるほど、これがマルチテナントのDBかーとなり、中身は…………sqlite !?

Androidアプリのデータベースだったり、ソシャゲのmasterデータだったりに使われてるのは知ってるけど、使ったことないが!?になり困惑です。 とりあえずログを出力するにはどうすればとコードを見ていると、とりあえず環境変数に突っ込むと見れそうなのでそれを使って出力してボトルネックの調査開始です。

出てきたログがクエリ毎に1つのJSON文字列を吐き出して、それをファイルに追記するタイプだったので、適当にvimとかで置換して jq で整形し、sortとかで遅いクエリを洗い出したり、uniqで回数を数えたりで全体感を把握します。

https://github.com/yamachu/isucon12-qualify/issues/4#issuecomment-1193075771

14:10ぐらい

sqlite側のDBにINDEXを貼りまくる

/initialize時に初期からある1~100までのDBに対してアクセスを行い、INDEXを貼ったり、最新のplayerのスコアしか採用しないことから、unique (player_id, tenant_id, competition_id) みたいな複合キーを使用したテーブルを作って、replace into ~ select で突っ込み直す作戦を取りました。 これならば30秒制限にも引っかからずsqliteのまま各DBの高速化が行えると踏んで行いました。

実際にINDEXも効くようになって割と高速化出来た記憶があります。

この時点で3212点。

15:50……え、1時間30分やってたのこれ………

ランキング取得APIの改善

GET /api/player/competition/:competitionId/ranking

で毎回playerを取得するクエリが走っていて、N+1じゃんに気づいたのでクエリの書き直しを実行。

これで若干スコア上がった記憶がある。

早そう · yamachu/isucon12-qualify@af38181 · GitHub

コードとしては間違ってあとから修正してるけど雰囲気こんな感じ。 この施策で一気に上がった。

4578点

16:30

今回のNode実装向けのチューニング

ts-nodeで今回走っていたけれども、ts-nodeをかませると走り出しとか若干遅くなったりするということを経験していたので、事前にtsc通してjsに落として、そのまま実行する形に修正。

これで100程度スコアが上がった。

4689点

ちょっと早いのでは · yamachu/isucon12-qualify@7303db8 · GitHub

16:40

playerをキャッシュしようとして出来なかった。

playerを毎回取得しているので、これは改善ポイントですね!となったけれども、全体取得とかのやつも存在したり、失格にした場合の反映漏れなどがあり泣く泣くrevert。 これが上手く回っていたらもう少しスコアが上がったんじゃないかなと思うので、落ち着いた頭でまた考えてみたい。

playerをcacheする · yamachu/isucon12-qualify@eb98340 · GitHub

fix · yamachu/isucon12-qualify@96c91ac · GitHub

直後にこの fix をrevertしているので、fix出来てねえじゃん!!と自分で大笑いしていた。

この時点で 17:20 で大焦り。

もう何も出来ないなと諦めログを止める

bye log · yamachu/isucon12-qualify@4c05dfb · GitHub

これで止めたつもりだったんだけど、実際はmysql側止めてなくて、その状態で最終スコア出していたことに気づきました。 はい。

4654点(あれっ、下がってる…

17:23

課金レポートの早期リターン

コードを眺めていたら早期リターンでクエリを減らせることに気づいたので実施。

請求早く · yamachu/isucon12-qualify@cf874b6 · GitHub

ちょっと上がったはず。 ここで5317点

17:40

大会スコアの入稿箇所の改善

後で余裕があったらやろうと思ってFIXMEで残しておいた部分に着手。 rowが最大の物、すなわち同じplayerなら最後に読んだ値が採用されることから、適当にplayer_idをキーとしたMapに対してreduceで畳み込んでしまって、そこから存在確認やらinsertすれば回数減るよねという考えがあったので実施。

頼む · yamachu/isucon12-qualify@c2da6d6 · GitHub

ここで5835点

17:45

参加者詳細情報取得APIのN+1の改善

FIXMEで残しておいたシリーズを15分前だけどまた片付け始めた。 単純にjoin一発で取れるやろーと思って試したけど、いつもどおりクエリにミスが発生していてベンチ回して気づくという。

ike · yamachu/isucon12-qualify@562bbf1 · GitHub

これの修正を書き始めたのが 17:57 で、修正コミットが 17:58 ベンチを回して失敗が出たらrevertしようと思って手元に準備していましたが、無事に17:59:53のタイミングでベンチが通ったのを確認。

この時点で6501点

までが実際にやったこと。

反省

やった後に一意のIDはuuidv4をアプリケーション側で発行すれば更に高速化出来るなとか思ったりしたので、発想力が足りなかった。

そして何よりも今回の大きな反省点としては、ボトルネック調査が勘頼りだったこと。 去年はalpとか使ったりしてエンドポイント単位で見て出来ていたけれども、今年は実際に発行されたクエリと時間から、だいたいこれ!!!!!で進めてしまっていた。

こういう計測系の導入だったり、slow query出すやつに時間をかけずに出来るように、何かしら秘伝のタレでも用意しておきたいなって思った。

別にみんな hidden のタレにしないで、オープンな秘伝のタレにしていいのよ!!!!!!!!!!!!!!!!!!!

というわけで、今年もものすごい楽しめたISUCONだった。 来年も引き続き個人スポンサーとしてISUCONを応援したいし、また1参加者として楽しみたいなと思った。

運営の方々本当にありがとうございました!!