こんにちは、ゲームソリューション部の入井です。
昨年2023年11月に開催されたISUCON13の問題が一般公開され、更に有志の方が簡単にAWS上に問題環境を構築できるAMIを公開されていたため、それを使って環境構築した上で簡単なDBチューニングによるベンチマークスコアアップを試してみました。
ISUCON13 イベントレポート : ISUCON公式Blog
環境構築
今回使用したのは@matsuuさんがこちらのリポジトリで公開されているAMIです。
matsuu/aws-isucon: ISUCON過去問環境をAWSで再現するための一式まとめ
今回のISUCON13だけでなく、ISUCON5時代からの過去問AMIが公開されており、かなりありがたいリポジトリです。
こちらを使用して以下のようなEC2インスタンスを1台AWS上に作成しました。
| インスタンスタイプ | EBSボリューム |
|---|---|
| c5.large | gp3 30 GiB |
VPCはパブリックサブネット1つのシンプルな構成です。
上記のAMIの中にWebサーバーもベンチマーカーも入っており、今回は1台のインスタンスの中で全て実行します。正確な計測をしたいのであればベンチマーカーのサーバーは分けておくべきですが、今回は気軽に過去問環境のチューニングをしたいだけなので環境は簡単にしています。
初回ベンチマーク実行
何もチューニングしないでベンチマークを実行した結果は以下の通りでした。ところどころのシナリオで失敗が発生しています。
$ ./bench run --enable-ssl
isupipe-benchmarker 配信を最後まで視聴できた視聴者数 {"viewers": 6}
staff-logger bench/bench.go:323 [シナリオ aggressive-streamer-moderate] 30 回成功
staff-logger bench/bench.go:323 [シナリオ dns-watertorture-attack] 8 回成功
staff-logger bench/bench.go:323 [シナリオ streamer-cold-reserve] 32 回成功
staff-logger bench/bench.go:323 [シナリオ streamer-moderate] 19 回成功
staff-logger bench/bench.go:323 [シナリオ viewer-report] 31 回成功, 3 回失敗
staff-logger bench/bench.go:323 [シナリオ viewer-spam] 32 回成功
staff-logger bench/bench.go:323 [シナリオ viewer] 6 回成功, 1 回失敗
staff-logger bench/bench.go:323 [失敗シナリオ viewer-fail] 1 回失敗
staff-logger bench/bench.go:323 [失敗シナリオ viewer-report-fail] 3 回失敗
staff-logger bench/bench.go:329 DNSAttacker並列数: 2
staff-logger bench/bench.go:330 名前解決成功数: 1304
staff-logger bench/bench.go:331 名前解決失敗数: 11
staff-logger bench/bench.go:335 スコア: 2133※ベンチマーカーの出力結果は見やすいように一部改変しています
INDEX追加によるDBチューニングとその結果
スロークエリログの出力と集計
今回はDBの簡単なチューニングを試してみます。
時間のかかっているクエリを判別するため、mysqlがスロークエリのログを出力するよう設定を変更します。
$ sudo vi /etc/mysql/mysql.conf.d/mysqld.cnfmy.cnfのスロークエリ関係設定のコメントアウトを以下のように外します。
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 0long_query_time はスロークエリと判定される秒数の設定です。この設定値よりも遅いクエリは全てスロークエリとしてログ出力されます。
今回は0に設定しているため全てのクエリがスロークエリと判定されてしまいますが、これは1件あたりのクエリ実行時間は短くても、全件の総実行時間で見ると他クエリよりも時間がかかっているクエリを見つけるための設定です。
もちろんスロークエリ出力自体がDBへの負荷はをかけてしまうため、あくまでチューニングを行うときのみ有用な設定となります。
スロークエリの出力設定を有効化した後、再度ベンチマークを実行します。これにより、/var/log/mysql/mysql-slow.logへログが出力されます。
このログは、スロークエリと判定されたクエリの実行にかかった時間が1件ずつ記録されているため、全てのクエリを出力している今回の場合ログからどのクエリに問題があるのかを特定するのは難しいです。
そこで、mysqldumpslowコマンドを使います。これは、スロークエリログを元にクエリごとの合計実行時間などの集計結果を確認できるコマンドです。
MySQL :: MySQL 8.0 リファレンスマニュアル :: 4.6.9 mysqldumpslow — スロークエリーログファイルの要約
今回は、以下のように集計結果をファイルへ出力した上でlessで中身を閲覧しました。mysqldumpslowでは-s tというオプションにより、合計実行時間の長いクエリ順に集計結果をソートしています。
$ sudo mysqldumpslow -s t /var/log/mysql/mysql-slow.log > slow-query-dump
$ less slow-query-dump集計結果は以下のようになりました（上位数件のクエリを抜粋）
Count: 3732 Time=0.05s (193s) Lock=0.00s (0s) Rows=3.0 (11115), isucon[isucon]@localhost
SELECT * FROM livestream_tags WHERE livestream_id = N
Count: 189276 Time=0.00s (77s) Lock=0.00s (0s) Rows=0.4 (79061), 2users@localhost
#
Count: 3786 Time=0.02s (68s) Lock=0.00s (0s) Rows=0.2 (892), isudns[isudns]@localhost
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=N and name='S' and domain_id=N
Count: 6351 Time=0.01s (52s) Lock=0.00s (0s) Rows=0.6 (3897), isucon[isucon]@localhost
SELECT image FROM icons WHERE user_id = N
Count: 2836 Time=0.01s (35s) Lock=0.00s (0s) Rows=0.5 (1462), isudns[isudns]@localhost
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=N and type='S' and name='S'
Count: 5284 Time=0.01s (30s) Lock=0.00s (0s) Rows=1.0 (5284), isucon[isucon]@localhost
SELECT * FROM themes WHERE user_id = N
Count: 2363 Time=0.01s (25s) Lock=0.00s (0s) Rows=1.0 (2363), isucon[isucon]@localhost
SELECT IFNULL(SUM(l2.tip), N) FROM users u
INNER JOIN livestreams l ON l.user_id = u.id
INNER JOIN livecomments l2 ON l2.livestream_id = l.id
WHERE u.id = N
Count: 2364 Time=0.01s (25s) Lock=0.00s (0s) Rows=1.0 (2364), isucon[isucon]@localhost
SELECT COUNT(*) FROM users u
INNER JOIN livestreams l ON l.user_id = u.id
INNER JOIN reactions r ON r.livestream_id = l.id
WHERE u.id = N一番時間のかかっていたクエリのチューニング
最初に、mysqldumpslowの集計結果で一番時間のかかっていた以下のクエリについてチューニングを行います。
Count: 3732 Time=0.05s (193s) Lock=0.00s (0s) Rows=3.0 (11115), isucon[isucon]@localhost
SELECT * FROM livestream_tags WHERE livestream_id = Nこのクエリはベンチマーク中に3,732回実行され、1回あたりの実行時間は0.05秒ですが合計で見ると193秒も時間がかかっています。
問題のクエリについて、EXPLAINで実行計画を確認してみると、keyがNullでインデックスが使われていません。
mysql> EXPLAIN SELECT * FROM livestream_tags WHERE livestream_id = 1 \G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: livestream_tags
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 10640
filtered: 10.00
Extra: Using whereテーブルの定義を見ると、クエリのWHEREで検索条件に使用していたlivestream_idにインデックスが作成されていませんでした。また、AUTO_INCREMENTの値からこのテーブルには約11,000件のデータが入っており、これは先ほどの実行計画のrowsの値と近い件数のため、1クエリごとにテーブル内のほぼ全てのデータを見に行っていることが分かります。
mysql> SHOW CREATE TABLE livestream_tags\G
*************************** 1. row ***************************
Table: livestream_tags
Create Table: CREATE TABLE `livestream_tags` (
`id` bigint NOT NULL AUTO_INCREMENT,
`livestream_id` bigint NOT NULL,
`tag_id` bigint NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=11174 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin
1 row in set (0.00 sec)明らかにインデックスが無いことがクエリ実行に時間がかかっている原因のため、livestream_idのインデックスを作成します。
mysql> ALTER TABLE livestream_tags add index livestream_id_idx(livestream_id);その後再度EXPLAINを実行すると、インデックスが使われrowsの数が激減していることが分かります。
mysql> EXPLAIN SELECT * FROM livestream_tags WHERE livestream_id = 1 \G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: livestream_tags
partitions: NULL
type: ref
possible_keys: livestream_id_idx
key: livestream_id_idx
key_len: 8
ref: const
rows: 2
filtered: 100.00
Extra: NULL
1 row in set, 1 warning (0.00 sec)チューニングの結果確認
この状態でベンチマーク結果がどの程度変わるのかを見てみます。
スロークエリログの変化も確認したいため、新しい結果のみを集計できるように一旦現在のスロークエリログを消去し、mysqlが新しいファイルへログを出力するようログフラッシュを実行します。
$ sudo rm /var/log/mysql/mysql-slow.log
$ sudo mysqladmin flush-logsベンチマークを実行すると、今度は以下のような結果でした。
$ ./bench run --enable-ssl
isupipe-benchmarker 配信を最後まで視聴できた視聴者数 {"viewers": 11}
staff-logger bench/bench.go:323 [シナリオ aggressive-streamer-moderate] 27 回成功, 2 回失敗
info staff-logger bench/bench.go:323 [シナリオ dns-watertorture-attack] 6 回成功
info staff-logger bench/bench.go:323 [シナリオ streamer-cold-reserve] 32 回成功, 1 回失敗
info staff-logger bench/bench.go:323 [シナリオ streamer-moderate] 30 回成功
info staff-logger bench/bench.go:323 [シナリオ viewer-report] 31 回成功, 8 回失敗
info staff-logger bench/bench.go:323 [シナリオ viewer-spam] 30 回成功
info staff-logger bench/bench.go:323 [シナリオ viewer] 11 回成功
info staff-logger bench/bench.go:323 [失敗シナリオ aggressive-streamer-moderate-fail] 2 回失敗
info staff-logger bench/bench.go:323 [失敗シナリオ streamer-cold-reserve-fail] 1 回失敗
info staff-logger bench/bench.go:323 [失敗シナリオ viewer-report-fail] 8 回失敗
info staff-logger bench/bench.go:329 DNSAttacker並列数: 2
info staff-logger bench/bench.go:330 名前解決成功数: 1154
info staff-logger bench/bench.go:331 名前解決失敗数: 4
info staff-logger bench/bench.go:335 スコア: 3051最終的なスコアが2,133から3,051へ上昇しています。シナリオの失敗は相変わらず多いですが、streamer-moderateというシナリオの成功数が19から30へと上がっていました。クエリを改善した結果、このシナリオの成功数が上昇しそれがスコアアップにつながっているのかもしれません。
つづいて、今回改善したクエリの集計結果は以下のような形でした。
Count: 4954 Time=0.00s (7s) Lock=0.00s (0s) Rows=3.3 (16391), isucon[isucon]@localhost
SELECT * FROM livestream_tags WHERE livestream_id = N合計193秒かかっていたのが7秒にまで短縮できました。インデックスの有無だけでも実行時間にかなりの差が生まれることが分かります。
まとめ
今回は、ISUCON13の過去問環境を構築し、その中でDBチューニングを試してみました。
インデックスが作成されていないせいで遅延しているクエリは今回紹介したもの以外にもかなりあり、それに対して適切なインデックスを作成するだけでスコアがどんどん上がっていきました。
様々なチューニングを簡単に試すことができる環境が手に入ったので、DBだけでなくアプリコードやアーキテクチャの改善など色々な方向性でチューニングをやってみようと思います。
3
