Gマイナー志向

とくに意味はありません

ISUCON12予選にシン・ウー馬場ーイー2として参加し、2位で予選突破しました

TL;DR

ISUCON12予選にシン・ウー馬場ーイー2 として出場しました。 結果、予選2位で本選出場をきめました。やったね。 最終スコアは75800、予選中のベストスコアは76525でした。本選もがんばるぞ！

毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます！！１

体制

あいこん なまえ やくわり ペアプロ
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 を目視確認
  • 負荷テスト後にアクセス解析
    • nginxのログをkataribeで解析して /result/kataribe.log に出力
    • MySQLのスロークエリーログをgo-mysql-query-digestで解析して /result/slowquery.log に出力
    • MySQLTunerを実行して /result/mysqltuner.log に出力
  • / で git init
    • /etc と /home と解析結果を含む /result をまるごとコミット(必要に応じて.gitignoreで除外)
    • git add / して git commit
    • GitHubのプライベートリポジトリに git push

リポジトリは競技終了後に公開しました。 github.com

最終構成

当初は1台目のみを使い、残り1時間のタイミングで複数サーバを使うように構成変更しました。

サーバ 構成要素 備考
1台目 nginx + app(go) nginxは1台目と3台目のappにround-robin
2台目 MySQL 初期実装のままバージョン変更なし
3台目 app(go) 1台目のapp(go)と同じ実装

ちなみに昨年こんなこと書いており

当初は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
}

github.com

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方式に置き換えています。

github.com

12:08 昼食タイム

昼食はしっかりとりましょう

12:50 6785 SQLiteにインデックス追加

前の対応でmysqldの負荷が大きく下がり、アプリ側の負荷になったことを確認しました。

isuportsのCPU使用率が圧倒的でsysとiowaitが高い

ここで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にも上記を盛り込んでいます。

github.com

14:05 5164 rankingのN+1を解消

インデックスを追加してisuportsプロセスの%CPUは下がったものの、sysとiowaitは下がらないことを確認。一旦まずはSQLの改善をできないかと考えてrankingの改善をを検討しています。まずranking内のN+1となっていた部分を解消させています。

github.com

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で、上記パラメータをそのまま適用はできなくなっています。お気をつけください。

mysql

-- 本番環境でやってはいけない
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

github.com

15:04 20303 インデックスの追加とinterpolateParamsを設定

SQLiteからMySQLに移行したのに合わせてボトルネックが再びMySQLになりはじめました。 MySQLのスロークエリーログを解析してインデックスを追加し、またPrepareが上位にきたのでGo実装の定番設定であるinterpolateParams=trueを追加しました。

ALTER TABLE player ADD INDEX (tenant_id, created_at DESC);

github.com

15:18 15672 competitionもMySQLへ移動してSQLite撤廃

まだSQLiteを利用していたcompetitionテーブルもMySQLへ移動させました。結果としてスコアは下がりましたが方向性は間違っていないはずと判断してそのまま突き進んでいます。

github.com

15:32 34464 参加者向けAPIのN+1を解消する

引き続き MySQLの％CPUが高いので、 GET /api/player/player/:player_id で呼ばれているcompetitionをベースとしたN+1をJOINすることで解消させています。

github.com

15:54 43629 flockを外してトランザクション実装に変更

SQLiteを使わない実装には切り替えていたものの、まだflockの削除は行っておらず、flockが原因と思われる余計な遅延をアクセスログの解析結果で確認していました。 そのためflockを外しつつ、問題が出ないようにトランザクション処理を実装しました。

github.com

16:03 44383 INSERT player後のSELECTを削除

playerへINSERTする際、INSERTした結果をSELECTする実装になっていましたが、INSERT時にID含め必要な情報はすべて揃っているため、SELECTを行わない実装に変更しました。

github.com

16:42 44268 last_player_scoreのデッドロック対策

捌ける量が増えてくるとlast_player_scoreのDELETEしてからINSERTする処理でデッドロックが発生していました。 この事象は今年のkayac社内ISUCONでも発生した事象で、「あ、これ進○ゼミでやったところだ！」となり以下のように変更しています。

  • 変更前：レコードをDELETEしてからREPLACE
  • 変更後：レコードをREPLACEしてから古いレコードをDELETE

github.com

16:52 44051 scoreのN+1を部分的に解消した

アクセスログを解析するとscoreが上位に来ていたので、N+1を可能な範囲で解消させました。スコアへの影響は微妙でしたがそのままとしています。

github.com

17:15 63991 サーバ分割（1台→2台構成）

まだ改善できる余地は見つけてはいたものの、残りの時間内ですぐに解消できそうになかったので、このタイミングでアプリとDBのサーバを分けることにしました。ここまでは1台で処理していました。

サーバ 変更前 変更後
1台目 nginx + app(go) + MySQL nginx + app(go)
2台目 利用なし MySQL
3台目 利用なし 利用なし

我々のチームは基本的にサーバ分割はやることがなくなったり終盤になってから行うようにしています。その理由はボトルネックとなる箇所は随時変わるので、序盤に分割してもボトルネック次第で載せ替え直す必要がでてくる可能性があるためです。

github.com

17:24 62301 POST scoreで空データが投げられた場合に対処

空データが投げられてエラーになる状況が発生したので空でもエラーにならないよう対処しました。

github.com

17:39 72760 サーバ分割（2台構成→3台構成）

引き続きボトルネックはMySQLのように見えたのですが、ベンチの後半でapp側の負荷が上がるシーンが発生していることを確認したので、3台目にもappを設置しました。結果スコアがさらに伸びることを確認しています。

サーバ 変更前 変更後
1台目 nginx + app(go) nginx + app(go)
2台目 MySQL MySQL
3台目 利用なし app(go)

github.com

17:47 76525 再起動対応と各種ログ無効化

再起動時のapp-db間接続の問題を回避するため秘伝のタレである StartLimitBurst を/etc/systemd/system/isuports.serviceに投入しています。これぞインフラ屋らしい運用でカバー作戦だ。

[Service]
StartLimitBurst=999

その他、各種ログの無効化を行いベストスコアは76525でした。再起動後に再度ベンチを行い75800が最終スコアとなっております。

github.com

*1:後から確認するとtargetやregistryはvolumesとしてマウントしてたのでdocker内でのcargo再ビルドは一応ケアされていた模様