ISUCON12予選に1人で挑み惨敗を喫しました

FAILでスコア0でフィニッシュです。ありがとうございました……。

経緯

今回のISUCON、チームワークの難しさに悩みすぎて血迷ったのでソロで出ます
— かるぱねるら (@karupanerura) 2022年7月9日

近頃、チームで仕事するの難しいなーと感じていたところ、気が狂い、いっそのこと俺一人で全部やりてーとなって、血迷いました。難しさから逃げるな。

やったこと

最初に動いているコードはGoでした。

Goのまま行ってもよかったのですが、せっかく好きな言語であるところのPerlの初期実装が用意されているわけだし、Perlを使うことでチームメイトが手を出しづらくなるわけでもないし、RDBを使った開発経験*1としては一番長いPerlで挑もうということでPerlに切り替えます。なにより、Perlで勝てたらカッコいいじゃんと思っていました。負けたが……。

兎にも角にも、まず計測。

ベンチを回し、事前に用意したAnsibleによってセットアップしたNetdataでOSリソースの消費バランスを見つつ、アクセスログをalpで集計しました。 ISUCON11予選と同様にセキュリティグループの変更は制限されていそうだったので、こんな具合でnginx経由でNetdataにアクセスできるようにしておきます。

        location /_netdata/isucon12q-1/ {
            access_log off;
            rewrite /_netdata/isucon12q-1/(.*) /$1 break;
            proxy_pass http://127.0.0.1:19999;
        }

        location /_netdata/isucon12q-2/ {
            access_log off;
            rewrite /_netdata/isucon12q-2/(.*) /$1 break;
            proxy_pass http://192.168.0.12:19999;
        }

        location /_netdata/isucon12q-3/ {
            access_log off;
            rewrite /_netdata/isucon12q-3/(.*) /$1 break;
            proxy_pass http://192.168.0.13:19999;
        }

https://github.com/karupanerura/isucon12-qualifier/blob/main/ansible/files/config/nginx.conf#L113-L129

オープニングムービーの通り、ランキングを提供するエンドポイントが圧倒的な処理時間を占めています。また、I/O waitが大変に高い値を示していることが分かりました。（本当はtopも見る手筈だったけどうっかり抜けていた。。）

では、と、実際にコードを読み始めてみるのですが、SQLiteだったので少々面食らいます。コード量も多く、焦りを感じます。

コード量も多く一人なのもあってつい焦ってしまい、I/O waitの原因は都度openしているSQLiteを通じた、ディスクへのアクセス過多だろうと早合点してしまいました。本来はちゃんと計測して切り分けをするべきです。

スキーマを見ると明らかにIndexが効いていないのでとりあえずIndexを貼ってベンチを流したところ、ほとんどスコアが変わりません。

実は、このとき、実はスキーマの定義ファイルだけを変更しただけで初期データに対してIndexを貼るのを忘れており、またしても早合点していました。これでは新しく作られたテナントに対してしかIndexが効かず、実際にはID=1のテナントがかなりヘビーに使われていたため、ほとんど効果がないのは当然です。この結果をすぐに疑うべきでしたが、ここでSQLiteのままチューニングすることに対する懐疑心が強くなります。

また、SQLiteのままでは、普段使っているMySQL向けのツールが使えません。 Profilerも用意されていましたが、初見のプロファイリングのログをうまく集計/解析して頑張ってSQLiteのままチューニングしきれる自信はありませんでした。

さらに、SQLiteからMySQLへの移行を補助する簡易なスクリプトも用意されているのを発見したので、MySQLへ頑張って移行するぞという気持ちが強くなります。

そして、MySQLへの移行を決意しました。すでに判断ミスが多い……。

テナントDBのMySQL移行

SQLiteのDBをMySQLに移行するにあたって、それぞれを別のデータベースとして作ってしまうのがよかろうという発想に自然となりました。データベース名は isucon_tenant_%d のようにしました。

そして、IDは数値なので、IDの2の余剰で2台に分散させることができそうです。実際にシャーディングするかはさておき、ベンチマーカーで負荷が高くなっていった際に新しくヘビーに使われるテナントが発生するシナリオはありえなくはなさそうですし、そういったテナントを隔離するためにもDBを選択できる実装にしておくのはよさそうな気がしたのでついでにやってしまうことにしました。

幸い、SQLiteのファイルがテナント毎に別れていためにそのようなシャーディングの実装は簡単にできそうでした。

どうせMySQLに移行するなら同時にスキーマも最適化してしまうことにします。幸い、今回は1人チームなので他のひとの作業をブロックすることはありません。

SQLiteからMySQLへの移行はそこそこ時間がかかりそうだったので、シャーディングすることを考えたときに同居する可能性があるAdmin DBをどうするか見ていきます。

Admin DBのRedis移行

Admin DBをどうするかを考えるためにスキーマと実装を追ってみると、 id_generator と visit_history がつらそうなことに気づきます。

いずれもハードに利用されるテーブルであり、特に visit_history はランキングを提供するエンドポイントにアクセスする度にINSERTされているのでボトルネックになりやすいかなり邪魔げです。しかし、実際には visit_history は.finished_at 以前の最終アクセス日時しか求められていないようでした。ランキングを提供するエンドポイントで finished_at 以前の期間だけ更新するようにすればRedisのSET型で十分そうです。これもついでにやってしまうことにしました。

id_generator もRedisでINCR/INCRBYを使って代替できそうです。UUIDやULIDに変えることも考えましたが、現状のID発番は連番となっておりそれをわざわざ16進数に変換して扱っていたため、連番であることや外形的に16進数表記であることに意味がある可能性があると考えてそれはやめておきました。なお、いずれも問題なかったそうです。残念。

これをやりきれば、Admin DBはテナントの定義だけになり、かなりシンプルになりそうです。負荷はほとんどなくせるでしょう。

ついでにガッと移行してしまうことにします。

テナントDBの最適化

SQLiteからMySQLへの移行がなかなか終わらないので、テナントDBの最適化も先回りして考え始めます。

ランキング情報を作るための player_score はCSV経由でインポートされます。 flockでロックを取ってアイソレーションが行われていますが、DELETEする際にtenant_idとcompetition_idで絞り込む際に適切にロックを取れるはずです。トランザクションにまとめることでこのflockは外せるでしょう。

また、N+1クエリとなっているクエリを読み解くと、各player_id毎に最後の行のスコアを採用してそれをscore順に並び替えていることがわかります。他の箇所でも最後の行以外は要求されていなさそうでした。CSVからインポートする際に各ユーザーごとに最後の行だけを採用すればよさそうです。（後述しますが、この考えは実際には少し間違っていました。）

ここで、初期データを修正する必要性に気付きますが、修正は窓関数を使えばSQL一発で出来るので他のALTERと一緒にやってしまえばよさそうです。（このときに、先のINDEXの適用が実はできてなかったと気づければ引き返せたのだけど、気付かず。）

SELECT
   id, tenant_id, competition_id, player_id, score, row_num, created_at, updated_at
FROM (
    SELECT
        id, tenant_id, competition_id, player_id, score, row_num, created_at, updated_at,
        ROW_NUMBER() OVER (PARTITION BY tenant_id, competition_id, player_id ORDER BY row_num DESC) AS `rank`
    FROM player_score) a
WHERE a.rank = 1;

実際には、idは使っている箇所がないのでDROPできますし、row_num も使うことはないので残す必要はありません。（後述しますが、この考えは実際には少し間違っていました。）

さらに、IDが16進数表記の文字列になっているわけで、単調増加なぶんB+Treeの挿入効率は悪くはないのですが、無駄にインデックスサイズが大きいのが気になります。（ボトルネックではないので）放っておけばいいものの、ついでなのでbigintにすることにしました。変換はMySQLのCONV関数で一発です。

……などを織り込んだものがこちらです:

-- competition
CREATE TABLE `competition_new` (
  `id` bigint NOT NULL,
  `tenant_id` bigint NOT NULL,
  `title` text NOT NULL,
  `finished_at` bigint DEFAULT NULL,
  `created_at` bigint NOT NULL,
  `updated_at` bigint NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;
INSERT INTO competition_new (id, tenant_id, title, finished_at, created_at, updated_at) SELECT CONV(id,16,10) AS id, tenant_id, title, finished_at, created_at, updated_at FROM competition;
RENAME TABLE competition TO competition_old, competition_new TO competition;
DROP TABLE competition_old;

-- player
CREATE TABLE `player_new` (
  `id` bigint NOT NULL,
  `tenant_id` bigint NOT NULL,
  `display_name` text NOT NULL,
  `is_disqualified` tinyint(1) NOT NULL,
  `created_at` bigint NOT NULL,
  `updated_at` bigint NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;
INSERT INTO player_new (id, tenant_id, display_name, is_disqualified, created_at, updated_at) SELECT CONV(id,16,10) AS id, tenant_id, display_name, is_disqualified, created_at, updated_at FROM player;
RENAME TABLE player TO player_old, player_new TO player;
DROP TABLE player_old;

--- player_score

CREATE TABLE `player_score_new` (
  `tenant_id` bigint NOT NULL,
  `player_id` bigint NOT NULL,
  `competition_id` bigint NOT NULL,
  `score` bigint NOT NULL,
  `created_at` bigint NOT NULL,
  `updated_at` bigint NOT NULL,
  PRIMARY KEY (`tenant_id`, `player_id`, `competition_id`),
  INDEX `ranking_idx` (`tenant_id`, `competition_id`, `score`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;
INSERT INTO player_score_new (tenant_id, competition_id, player_id, score, created_at, updated_at) SELECT tenant_id, CONV(competition_id,16,10) AS competition_id, CONV(player_id,16,10) AS player_id, score, created_at, updated_at FROM (SELECT id, tenant_id, competition_id, player_id, score, created_at, updated_at, ROW_NUMBER() OVER (PARTITION BY tenant_id, competition_id, player_id ORDER BY row_num DESC) AS `rank` FROM player_score) a WHERE a.rank = 1;
RENAME TABLE player_score TO player_score_old, player_score_new TO player_score;
DROP TABLE player_score_old;

https://github.com/karupanerura/isucon12-qualifier/blob/main/sql/pre_convert.sql

お気づきでしょうか。せっかくtalentごとにDB分けてるのにうっかりtenant_idを抜くのを忘れています。ちょっともったいないですが些細なことなのでそのまま先に進みます。

このあたりを組み終わった頃に様子をみてみると、なかなかSQLiteからMySQLへの移行スクリプトが終わらないことに気付きます。 SHOW FULL PROCESSLIST を打って進捗を確認してみると、どうやらすごい量のplayer_scoreを持っているようです。

こりゃ大変だということで並列でインポートすることを試みます。 seq 1 100 | xargs -P10 -I{} bash -c './sql/sqlite3-to-sql ../initial_data/{}.db | mysql -uisucon isuports_tenant_{}' みたいな具合で並列で入れることにします。この時点では、ろくに見積もりも取らずに、どうせ実装時間は取られるのだし並行で移行を進めておけば時間の無駄にはならなかろうと高をくくっていました。見積もりくらい取るべきでした。

実装デバッグ祭り

このあたりの実装をいったん終えたのが15:21頃だったようです。

github.com

新しいスキーマに合わせていざベンチ実行！コケたー！というわけで修正まつりです。

様々な問題、考慮漏れが次々と見つかります。visit_historyのRedis移行に対するPOST /initializeへの対応漏れや、同様に初期化におけるテナントDBのDROP DATABASE漏れ。さらには、IDのURL上での16進数表記との相互変換漏れや、数年ぶりに使うSQL::Makerの使い方のミスなど、実に様々な問題を発見しますが一向にFAILは解消されず、刻一刻と時間が過ぎていきます。

最後まで残った問題が 大会内のランキング取得: ページングなし,上限100件 GET /api/player/competition/9fa52466/ranking 大会のランキングの1位のプレイヤーが違います (want: 9fa524cb, got: 9fa5252f) tenant:et-vrj-1659142684 role:player playerID:9fa524cb competitionID:9fa52466 rankAfter: というものです。新しく作成されたテナントのもので、WebUIで確認しようにもログインセッションの発行の仕方が分からず（事前にちゃんと確認しておけばよかった……）、バグの原因が分からぬままモンキーデバッグを繰り返し、タイムアップを迎え、敗北が確定しました。

感想戦

なお、ベンチが公開されたので追試しつつデバッグを進めたところ、ベンチマーカーのレスポンスのログからすべてのプレイヤーが同一のスコアであった場合のランキングが正しくなかった事がわかりました。

ランキングでは同じスコアの場合はrow_numの昇順に並べなければならないのを見落としていてバグっていた……
— かるぱねるら (@karupanerura) 2022年7月30日

修正内容としては以下です。

https://github.com/karupanerura/isucon12-qualifier/compare/main...study#diff-500630450a78877efc40cad8ce8ee6addd162a6bbe0ccf2bc9cd8cfaeae750ecR2

row_num をDROPしていたのを残すようにして、 INDEX ranking_idx (competition_id, score DESC, row_num) のインデックスを貼ることでクエリ一発でいい感じに取れるようにしています。

結果はこんな感じでした。

ベンチ公開されたのでバグ直して試したらSCORE: 20412、そのまま当初試そうと思っていた複数台構成にしたらSCORE: 24119だった。くやし〜
— かるぱねるら (@karupanerura) 2022年7月30日

ほか、tenant_idをDROPしたり、 ORDER BY created_at 向けにインデックスを貼ったり細かいことをしているのでその影響も多少はあるかもしれませんが、デバッグ用にアプリケーションのAccessLogを有効にしているのも入っているので影響はほぼトントンでしょう。

もしこれが17時くらいにできていれば、複数台構成にしたりログを切ったりすることで3万点台は確実に狙えただろうと思うと悔しい限りです。

KPT

KEEP
- 小手先だけではない根本的な改善に手を出せた
  - 効果の小さい細かい手を次々と打っていくうちにタイムアップを迎えてしまう。といったことは避けられた
- Perlで戦えた
  - FAILで終了してしまったがそこそこのスコアが出るくらいの改善には向かえていた
- 準備したものは役に立った
  - ISUCON寄りな技術メモをScrapboxで公開 https://scrapbox.io/karupanerura/
  - 手順書はリポジトリ isucon12-qualifier/README.md at main · karupanerura/isucon12-qualifier · GitHub
  - Ansibleも少しトラブったけどちゃんと使えた isucon12-qualifier/ansible at main · karupanerura/isucon12-qualifier · GitHub
PROBLEM
- 計測のツメが甘い
  - 焦ったのもあるがボトルネックとなっているプロセスすらちゃんと特定せずに手を出したのはダメだった
  - 効果が思ったほど出なかった打ち手はその原因をちゃんと追求するべき
- 計測と改善のサイクルがちゃんと回せていない
  - "改善"をデカくしすぎた
  - ついでに変えるのをやりすぎ
    - 先回りが良い方向に働いた部分もあったはずだけど確実性を欠いている
    - 結果的に博打っぽい打ち手になってしまった
    - 効果がそんなに見込めない打ち手に時間を使ってしまった(e.g. IDの16進数→10進数変換)
- 一気にたくさん変えすぎた
  - 変更を一気に入れすぎてデバッグのサイクルを素早く回せなかった
- 動作確認環境として他のサーバーを活かせなかった
  - MySQLへの移行とかは遊んでるサーバーでやっておいて、その間にSQLiteのままできる改善を進めておけばよかった
  - これができていれば、ULIDにシュッと変えてみて試しにベンチ流してみる。といったことを気軽に試せたはず
TRY
- 焦らずちゃんと計測する
  - 問題の原因をちゃんと明らかにしてから次へ進む
- ボトルネック以外には手を出さない
  - 特に、IDの16進数→10進数変換とかやる必要なかった。コードの変更箇所多すぎて時間的なコスパ悪い打ち手だった
  - 本当に手軽にできそうかちゃんと考えてから取り組む
- 動作確認環境として他のサーバーを活かす
  - DBのオペレーションとか、ベンチ回しやすいところではやらないほうが他の作業をブロックしないのでよい

感想

今回の #isucon の問題、言葉通り本当に良かったと思っていて、昨今のISUCONといえばこういう感じみたいなのをいい意味で裏切って、初見の問題を限られた制約の中でいかに精度高く解決するかを競って最強を決めるという本質的な面白さに引き戻してくれた感があった
— かるぱねるら (@karupanerura) 2022年7月24日

解いていて面白かったです！ありがとうございました！次こそは……。

*1:GoでのWebアプリケーションの開発経験の大半はGoogle CloudでCloud Firestore(Datastore mode)を使うことが殆どでRDBの出番がなかった。

時計を壊せ

駆け出してからそこそこ経ったWebプログラマーの雑記