ISUCON12予選にシン・ウー馬場ーイー2として参加し、2位で予選突破しました
TL;DR
ISUCON12予選にシン・ウー馬場ーイー2 として出場しました。 結果、予選2位で本選出場をきめました。やったね。 最終スコアは75800、予選中のベストスコアは76525でした。本選もがんばるぞ!
毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます!!1
体制
あいこん | なまえ | やくわり | ペアプロ |
---|---|---|---|
matsuu | バリバリ実装する前衛 | ドライバー | |
netmarkjp | 司令塔+ベンチ実行+結果解析 | ナビゲーター | |
ishikawa84g | セキュリティ+情報官+動作確認 AppArmor、マニュアルや公式アナウンスの把握、ブラウザでの挙動確認 |
ナビゲーター |
今年も3人が別々の場所からリモート参加です。 コミュニケーションはDiscordを使ってます。3人それぞれの画面を共有しながら音声チャットつなぎっぱなしです。
手元の環境
どうでもいい話ですが物理スペックです。
項目 | 品名 |
---|---|
メイン機 | Mac mini(M1, 2020) NEW! + モニター2台 |
キーボード | Magic Keyboard NEW! |
マウス | logicool ELGO M575 NEW! |
イヤホン | Shokz Aeropex |
マイク | marantz MPM-1000U |
椅子 | Ergohuman Basic NEW! |
値上げ発表後にヨドバシで駆け込み購入したMac miniです。購入費用はISUCONの優勝賞金の前借りです(皮算用)。
使用したツールなど
ツール | 用途 |
---|---|
sshrc | ssh接続時に手元の環境を持ち込むため |
tmux | ターミナル分割など |
neovim NEW! | エディタ |
top | リソース使用状況確認 |
dstat | リソース使用状況確認 |
MySQLTuner | MySQLパラメータ確認 |
kataribe | アクセスログ解析 |
go-mysql-query-digest NEW! | MySQLスロークエリー解析 |
今回vimからneovimに乗り換えました。設定はこちら。 pt-query-digestが解析に時間がかかることに業を煮やして拙作go-mysql-query-digestを導入しました。
方針
- サーバ上で直接neovimでソースコードを変更するスタイル
- 手元での再現環境構築や外部からのデプロイは行わない
sshrc
で環境がかぶらないようにしてメンバーごとにnvim/ssh環境を分離
- 実装言語はまずはRustを選択、問題が出たらGoを選択
- 負荷テスト中は
top
とdstat -tlamp
を目視確認 - 負荷テスト後にアクセス解析
/
でgit init
リポジトリは競技終了後に公開しました。 github.com
最終構成
当初は1台目のみを使い、残り1時間のタイミングで複数サーバを使うように構成変更しました。
サーバ | 構成要素 | 備考 |
---|---|---|
1台目 | nginx + app(go) | nginxは1台目と3台目のappにround-robin |
2台目 | MySQL | 初期実装のままバージョン変更なし |
3台目 | app(go) | 1台目のapp(go)と同じ実装 |
ちなみに昨年こんなこと書いており
— matsuu(シン・ウー馬場ーイー2) (@matsuu) 2021年10月7日当初はRustで進めていたんですが、競技中にRustからGoに切り替えました。😥
スコア推移
大きな飛躍はなく順当にボトルネックを潰したようなスコア推移になりました。
ベンチマーク履歴
今回はベンチを回した回数は少なめになりました。
やったこと
時間 スコア 概要
でまとめていきます。
10:04 - 間違えてバージニア北部リージョンにCloudFormationスタック作成してしまう
開始早々やってしまいました。東京リージョンで作成すべきCloudFormationスタックをバージニア北部リージョンで作成してしまいました。運良く早い段階で気づいて作成完了する前に削除しています。
10:06 - 東京リージョンでCloudFormationスタックを再作成
バージニア北部で作成していることに気づいて東京リージョンで作り直しています。
10:11 - サーバにSSH接続、環境構築
3台のサーバが作成されたことを確認したのでSSHで接続、環境構築をしています。我々はサーバ上で直接編集するスタイルですのでサーバ上にnvimを用意しています。
nvimはAppImageで持ち込んでますが、今回 libfuse.so.2
がインストールされてなかったので --appimage-extract
で展開しました。
nvim --appimage-extract rm nvim ln -s squashfs-root/AppRun nvim
10:25 0 Rustで初回ベンチ失敗
言語をRustに切り替えて初回ベンチを回しましたが0点でした。docker compose上はrunningになのに正常に応答できない原因を調べていたんですが、なんと5分近く経過してもcargo buildがまだ終わってなかったというオチ。まじかよ厳しいなRust。
繰り返しbuildすることを考えるとDocker環境では厳しいと判断してDockerを剥がす対処を行いました。*1
剥がして再ビルドを行なっている間にベンチ前準備スクリプト、ベンチ後解析スクリプト、解析用にログ出力などを整備しています。
10:45 2601 Rustでベンチ初成功
開始から45分経過してようやくベンチに成功しました。 ベンチ結果を解析するためのkataribe設定ファイルの整備などをこのタイミングで実施しています。
10:54 - 当日マニュアル読み合わせ
@ishikawa84g が整備してくれた当日マニュアルまとめ(プレゼン資料)の読み合わせをおこなっています。必要な情報だけを抽出してくれるのでとても助かっています。
11:22 - UUIDにあたりをつけるもcargo buildによってメモリ不足でサーバが固まりGoへの移行を決意
topコマンドでmysqldのCPU使用率が高いことを確認したのでMySQLのスロークエリーを確認、ユニークなキーを降り出す id_generator
テーブルに対するクエリーが遅いことを確認しています。
当初AUTO_INCREMENTでいいのでは?と考えましたがテーブルまたぎでユニークなIDを割り振っていることが判明、しかし格納先の各テーブルのIDがVARCHAR(255)であることを確認したのでUUIDで格納する方針にしました。uuid crateを使って実装していたんですが…
ここで競技サーバ(メモリ4GB)上でnvim+rust-analyzerを開きながらcargo buildを実行したせいでメモリが枯渇、SSH操作ができなくなりました。ohまじか。メモリ足りない。厳しい。
なんとかAWS管理コンソールからサーバを再起動して復旧させたものの、このまま進めるのは難しいと判断してRust言語を諦め、Go言語への切り替えを決断しました。
11:38 2493 Goで初ベンチ
Go言語もDockerから剥がした上で初ベンチを実施しています。ようやくここが我々のスタートラインだ。
11:43 3831 UUID実装に切り替え
Rust実装の際に検討していたUUIDへの切り替えをこのタイミングで適用しました。スコアがちょっと伸びてます。
func dispenseID(ctx context.Context) (string, error) { return uuid.NewString(), nil }
12:06 4936 visit_historyをvisitに置き換え
まだmysqldのCPU負荷が高いのでMySQLのスロークエリーを確認したところ visit_history
が最上位にきていることを確認。しかしSELECTしているのは1ヶ所しかなくUPDATEやDELETEもなし、また一番最初のレコードしか必要がないと判明したので、visit_historyへのINSERTをやめて別テーブルvisit
を作って集計自体をやめる実装に切り替えることにしました。
CREATE TABLE visit ( `tenant_id` BIGINT UNSIGNED NOT NULL, `competition_id` VARCHAR(255) NOT NULL, `player_id` VARCHAR(255) NOT NULL, `created_at` BIGINT NOT NULL, PRIMARY KEY (tenant_id, competition_id, player_id) ) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;
初期データは流し込みinitializeで流し込み。
TRUNCATE TABLE visit; INSERT INTO visit (tenant_id, competition_id, player_id, created_at) SELECT tenant_id, competition_id, player_id, MIN(created_at) AS min_created_at FROM visit_history GROUP BY tenant_id, competition_id, player_id;
これが23秒近くクエリーだったのでちょっとヒヤヒヤものでしたが、あとで流し込みではなくdump/restore方式に置き換えています。
12:08 昼食タイム
昼食はしっかりとりましょう
12:50 6785 SQLiteにインデックス追加
前の対応でmysqldの負荷が大きく下がり、アプリ側の負荷になったことを確認しました。
ここでSQLiteのままでは厳しいのではないかと判断しMySQLへの移行を検討しています。webapp/sql/配下に移行で使えるsqlite3-to-sql スクリプトが存在し、これをそのまま使えるのではと検討。ですが、その前にまずはSQLiteにインデックスがなかったのでインデックスを追加しました。インデックスはMySQLに移行しても利用できますからね。
CREATE INDEX player_score_idx1 ON player_score (tenant_id, competition_id, player_id, row_num DESC); CREATE INDEX player_score_idx2 ON player_score (tenant_id, competition_id, row_num DESC); CREATE INDEX competition_idx1 ON competition (tenant_id, created_at DESC); CREATE INDEX player_idx1 ON player (tenant_id, created_at);
SQLiteの初期化にはinitial_data配下がコピー元になっていたのでinitial_data配下のdbファイルにインデックスを追加、また随時DBが追加されるのでwebapp/tenant/10_schema.sqlにも上記を盛り込んでいます。
14:05 5164 rankingのN+1を解消
インデックスを追加してisuportsプロセスの%CPUは下がったものの、sysとiowaitは下がらないことを確認。一旦まずはSQLの改善をできないかと考えてrankingの改善をを検討しています。まずranking内のN+1となっていた部分を解消させています。
N+1の解消はスコアが下がってしまったのですが、これは次の布石のため必要になると判断してそのまま続行しています。
14:43 13349 SQLiteのデータをMySQLに移行しつつ最終スコア記録用テーブルの作成
tenantDBの各テーブルにはtenant_idカラムが含まれておりきちんとデータが入っていたので、テーブルを分ける必要はないと判断して1つのテーブルにすべて集約することにしました。 webapp/sql/sqlite3-to-sqlを使って初期データの全テーブルをMySQLに流し込んでいます。
MySQLへのデータ流し込みに時間がかかることを想定し、
for f in initial_data/*.db ; do echo $f ; webapp/sql/sqlite3-to-sql $f | mysql -u isucon -pisucon isuports ; done
なお、この実行にとても時間がかかるのですが、redo logの無効化などをおこなって処理の軽量化をおこなっています。
/etc/apparmor.d/usr.sbin.mysqld
/dev/shm/ r, /dev/shm/** rwk,
/etc/mysql/mysql.conf.d/mysqld.cnf
# 本番環境でやってはいけない innodb_log_file_size = 64M innodb_doublewrite = 0 innodb_flush_log_at_trx_commit = 0 innodb_flush_log_at_timeout = 3 innodb_log_group_home_dir = /dev/shm
2022/07/31追記:7/27にリリースされたMySQL 8.0.30で、上記パラメータをそのまま適用はできなくなっています。お気をつけください。
-- 本番環境でやってはいけない ALTER INSTANCE DISABLE INNODB REDO_LOG;
ソースコードを注意深く読んだところ、必要なのはtenant, competition, playerごとに最終スコアだけだと判断できたので、それを記録するためのlast_player_scoreテーブルを作成しました。
CREATE TABLE last_player_score ( tenant_id BIGINT NOT NULL, player_id VARCHAR(255) NOT NULL, competition_id VARCHAR(255) NOT NULL, score BIGINT NOT NULL, row_num BIGINT NOT NULL, created_at BIGINT NOT NULL, updated_at BIGINT NOT NULL, INDEX last_player_score_idx1 (tenant_id, competition_id, score DESC, row_num ASC), PRIMARY KEY (tenant_id, player_id, competition_id) );
player_scoreにはすでにたくさんのレコードが登録されており、そこからlast_player_scoreを含めたデータの生成を毎回initializeでやっていると時間がいくらあっても足りないので、player, last_player_scoreはmysqldumpした結果をinitialize時に流し込むようにしています。
INSERT INTO last_player_score SELECT tenant_id, player_id, competition_id, score, row_num, created_at, updated_at FROM player_score WHERE (tenant_id, player_id, competition_id, row_num) IN (SELECT tenant_id, player_id, competition_id, MAX(row_num) FROM player_score GROUP BY tenant_id, player_id, competition_id);
mysqldump -u isucon -pisucon isuports player > ~/webapp/sql/admin/player.dump mysqldump -u isucon -pisucon isuports last_player_score > ~/webapp/sql/admin/last_player_score.dump
15:04 20303 インデックスの追加とinterpolateParamsを設定
SQLiteからMySQLに移行したのに合わせてボトルネックが再びMySQLになりはじめました。 MySQLのスロークエリーログを解析してインデックスを追加し、またPrepareが上位にきたのでGo実装の定番設定であるinterpolateParams=trueを追加しました。
ALTER TABLE player ADD INDEX (tenant_id, created_at DESC);
15:18 15672 competitionもMySQLへ移動してSQLite撤廃
まだSQLiteを利用していたcompetitionテーブルもMySQLへ移動させました。結果としてスコアは下がりましたが方向性は間違っていないはずと判断してそのまま突き進んでいます。
15:32 34464 参加者向けAPIのN+1を解消する
引き続き MySQLの%CPUが高いので、 GET /api/player/player/:player_id
で呼ばれているcompetitionをベースとしたN+1をJOINすることで解消させています。
15:54 43629 flockを外してトランザクション実装に変更
SQLiteを使わない実装には切り替えていたものの、まだflockの削除は行っておらず、flockが原因と思われる余計な遅延をアクセスログの解析結果で確認していました。 そのためflockを外しつつ、問題が出ないようにトランザクション処理を実装しました。
16:03 44383 INSERT player後のSELECTを削除
playerへINSERTする際、INSERTした結果をSELECTする実装になっていましたが、INSERT時にID含め必要な情報はすべて揃っているため、SELECTを行わない実装に変更しました。
16:42 44268 last_player_scoreのデッドロック対策
捌ける量が増えてくるとlast_player_scoreのDELETEしてからINSERTする処理でデッドロックが発生していました。 この事象は今年のkayac社内ISUCONでも発生した事象で、「あ、これ進○ゼミでやったところだ!」となり以下のように変更しています。
- 変更前:レコードをDELETEしてからREPLACE
- 変更後:レコードをREPLACEしてから古いレコードをDELETE
16:52 44051 scoreのN+1を部分的に解消した
アクセスログを解析するとscoreが上位に来ていたので、N+1を可能な範囲で解消させました。スコアへの影響は微妙でしたがそのままとしています。
17:15 63991 サーバ分割(1台→2台構成)
まだ改善できる余地は見つけてはいたものの、残りの時間内ですぐに解消できそうになかったので、このタイミングでアプリとDBのサーバを分けることにしました。ここまでは1台で処理していました。
サーバ | 変更前 | 変更後 |
---|---|---|
1台目 | nginx + app(go) + MySQL | nginx + app(go) |
2台目 | 利用なし | MySQL |
3台目 | 利用なし | 利用なし |
我々のチームは基本的にサーバ分割はやることがなくなったり終盤になってから行うようにしています。その理由はボトルネックとなる箇所は随時変わるので、序盤に分割してもボトルネック次第で載せ替え直す必要がでてくる可能性があるためです。
17:24 62301 POST scoreで空データが投げられた場合に対処
空データが投げられてエラーになる状況が発生したので空でもエラーにならないよう対処しました。
17:39 72760 サーバ分割(2台構成→3台構成)
引き続きボトルネックはMySQLのように見えたのですが、ベンチの後半でapp側の負荷が上がるシーンが発生していることを確認したので、3台目にもappを設置しました。結果スコアがさらに伸びることを確認しています。
サーバ | 変更前 | 変更後 |
---|---|---|
1台目 | nginx + app(go) | nginx + app(go) |
2台目 | MySQL | MySQL |
3台目 | 利用なし | app(go) |
17:47 76525 再起動対応と各種ログ無効化
再起動時のapp-db間接続の問題を回避するため秘伝のタレである StartLimitBurst
を/etc/systemd/system/isuports.serviceに投入しています。これぞインフラ屋らしい運用でカバー作戦だ。
[Service] StartLimitBurst=999
その他、各種ログの無効化を行いベストスコアは76525でした。再起動後に再度ベンチを行い75800が最終スコアとなっております。
*1:後から確認するとtargetやregistryはvolumesとしてマウントしてたのでdocker内でのcargo再ビルドは一応ケアされていた模様