【負荷試験】AWS上でISUCON13の過去問環境を構築して簡単なDBチューニングをやってみた

こんにちは、ゲームソリューション部の入井です。

昨年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.cnf

my.cnfのスロークエリ関係設定のコメントアウトを以下のように外します。

slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time = 0

long_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だけでなくアプリコードやアーキテクチャの改善など色々な方向性でチューニングをやってみようと思います。