遅いクエリを突き止める!MySQLクエリ解析にスロークエリログを導入する手順

こんにちは。仁科(@nishina555)です。

Webのパフォーマンス改善において、SQLのクエリ解析は非常に重要です。
特に、実行時間の長いものや試行回数の多いクエリを抽出することはチューニングの方向性を決める上で大事です。

MySQLではスロークエリログの設定をすることで実際に実行されたクエリの分析をすることができます。
しかし、スロークエリログはデフォルトでは出力されていないため、MySQLの設定を変更する必要があります。

そこで今回はMySQLのクエリ解析を行う上で重要なスロークエリログの出力設定と実際のログの確認方法について説明をしていきます。

なお、今回の内容は、ISUCON7(予選)過去問環境をConoHaで構築する手順でConoHaに作成したISUCON環境を元に説明をしていきますので、ISUCONの環境を用意されていない方は適宜自分の環境に読みかえていただければと思います。

MySQLのバージョンは5.7.22を利用します。

スロークエリログを出力するためには設定を変更する必要がある

まずはスロークエリログがデフォルトでオフになっているので、出力するように設定を変更します。
設定は設定ファイルを編集する方法とMySQLのコンソールで変更する方法の2種類があります。

設定方法1: my.cnfにスロークエリログの設定を追記する

スロークエリログの設定は/etc/mysql/my.cnfに記述していきます。

$ sudo vim /etc/mysql/my.cnf

例えば以下のような設定を記述します。

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 0

変数とその意味については以下のようになっています。

つまり、上記の例は/var/log/mysql/slow.logに実行時間が0秒以上(= 全てのクエリ)を出力する(slow_query_log = 1)ということを意味しています。
例えば、long_query_timeを0.3とすれば0.3秒以上かかったクエリを抽出します。

なお、MySQL5.0より前の場合は少し仕様が違うので古いMySQLを利用する場合は注意が必要です。
異なる点としてはlong_query_timeが整数でしか指定できない点、出力ファイル先の変数がslow_query_log_fileではなくlog-slow-queriesである点です。

設定方法2: MySQLのコンソールで直接設定する

スロークエリログの設定はMySQLのコンソールで直接変更することも可能です。
先ほどの設定をコンソールで行う場合は以下のようになります。

mysql> set global slow_query_log_file = ' /var/log/mysql/slow.log';
mysql> set global long_query_time = 0;
mysql> set global slow_query_log = ON;

スロークエリログの設定終了後、アプリケーションとMySQLを再起動する

設定を反映させるためMySQLを再起動させます。

$ sudo systemctl restart mysql
もしくは
$ sudo service mysql restart

アプリケーションもDB接続が切れてエラーになる可能性があるので再起動させます。

$ sudo systemctl restart isubata.ruby.service

実際に設定が反映されているかMySQLのコンソールで確認する

では実際に設定が反映されているかMySQLのコンソールで確認していきます。

まずはMySQLにログインします。

$ sudo mysql

variablesを確認して先ほどの設定が反映されていればOKです。

mysql> show variables like 'slow%';

+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_launch_time    | 2                       |
| slow_query_log      | ON                      |
| slow_query_log_file | /var/log/mysql/slow.log |
+---------------------+-------------------------+
3 rows in set (0.00 sec)

mysql> show variables like 'long%';

+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

ベンチマークの実行

ここまで準備できたらベンチマーク、つまりクエリの実行をします。

ベンチマークのコマンドはConoHaの公式ページに書いてあるものを参考にします。

$ /home/isucon/isubata/bench/bin/bench -data=/home/isucon/isubata/bench/data -remotes=localhost -output=result.json

スロークエリログの確認方法とデータの読み方

ではスロークエリログを確認していきます。
クエリの確認にはmysqldumpslowというコマンドを使うことでスロークエリの集計等を行うことができます。

例えば、以下のようなコマンドで得られる実行結果は次のようになります。

$ sudo mysqldumpslow /var/log/mysql/slow.log

Reading mysql slow query log from /var/log/mysql/slow.log
Count: 41  Time=1.71s (70s)  Lock=0.00s (0s)  Rows=14.9 (611), isucon[isucon]@localhost
  SELECT * FROM image WHERE name = 'S'

Count: 902  Time=0.01s (5s)  Lock=0.00s (0s)  Rows=1.0 (902), isucon[isucon]@localhost
  SELECT COUNT(*) as cnt FROM message WHERE channel_id = N

Count: 4531  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (4531), isucon[isucon]@localhost
  SELECT name, display_name, avatar_icon FROM user WHERE id = N

Count: 14306  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=0.9 (13218), 2users@localhost
  #

Count: 10  Time=0.06s (0s)  Lock=0.00s (0s)  Rows=12.9 (129), isucon[isucon]@localhost
  SELECT * FROM message WHERE channel_id = N ORDER BY id DESC LIMIT N OFFSET N

ラベルの意味は以下のようになっています。

mysqldumpslowのオプションについて

mysqldumpslowにはオプションが存在しスロークエリログの表示形式を変えることができます。

例えば-sでオプションでソートする基準を選ぶことができます。
なお、mysqldumpslowはデフォルトではクエリの平均実行時間(at)で結果をソートして表示します。

変数とソート対象の対応は以下のようになっています。

その他のオプションは-hのヘルプで確認して下さい。

ここでは実際にソートオプションを利用してスロークエリログの結果を変更してみます。

以下はクエリの平均実行時間でソートしたものです。

$ sudo mysqldumpslow -s at /var/log/mysql/slow.log

Reading mysql slow query log from /var/log/mysql/slow.log
Count: 41  Time=1.71s (70s)  Lock=0.00s (0s)  Rows=14.9 (611), isucon[isucon]@localhost
  SELECT * FROM image WHERE name = 'S'

Count: 10  Time=0.06s (0s)  Lock=0.00s (0s)  Rows=12.9 (129), isucon[isucon]@localhost
  SELECT * FROM message WHERE channel_id = N ORDER BY id DESC LIMIT N OFFSET N

Count: 1  Time=0.03s (0s)  Lock=0.01s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  DELETE FROM user WHERE id > N

Count: 3  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  UPDATE user SET avatar_icon = 'S' WHERE id = N

Count: 3  Time=0.01s (0s)  Lock=0.08s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  INSERT INTO image (name, data) VALUES ('S', 'S')

次にクエリの出現回数でソートした例をのせます。
出現回数でソートすることで例えば、1回の実行時間が短くても回数が多いために負荷をかけているというクエリを見つけることができます。

$ sudo mysqldumpslow -s c /var/log/mysql/slow.log

Reading mysql slow query log from /var/log/mysql/slow.log
Count: 14306  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=0.9 (13218), 2users@localhost
  #

Count: 6951  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Close stmt

Count: 6942  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

Count: 4531  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (4531), isucon[isucon]@localhost
  SELECT name, display_name, avatar_icon FROM user WHERE id = N

Count: 902  Time=0.01s (5s)  Lock=0.00s (0s)  Rows=1.0 (902), isucon[isucon]@localhost
  SELECT COUNT(*) as cnt FROM message WHERE channel_id = N

Count: 900  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (8), isucon[isucon]@localhost
  SELECT * FROM haveread WHERE user_id = N AND channel_id = N

Count: 443  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  SET SESSION sql_mode='S'

もう1度スロークエリログを解析する時はログローテートする

パフォーマンスチューニング後、改めてベンチマークを実行する場合は前回のログが残っていると正しい解析ができません。

そこで、改めてベンチマークをとる場合はログをローテートしておきましょう。

ログローテートとは、ログのファイル名を別名に変更して、ひとつのログファイルにログが蓄積され続けないようにするものです。

また、スロークエリログ(ここでいう /var/log/mysql/slow.log)はファイル自体が存在しないと出力先ファイルがないということでエラーになってしまうので注意が必要です。

以下のコマンドでは、現在のログを日付付きのファイル名に変更し、mysqladmin flush-logsでログファイルを新しく作成しています。

$ now=`date +%Y%m%d-%H%M%S` && sudo mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$now && sudo mysqladmin flush-logs

まとめ

今回はクエリ解析をするためにMySQLにスロークエリログを導入する手順と実際のログの見方について説明しました。

特に、ISUCONに参加する場合はスロークエリの導入や解析は事前に手順書やチートシートを用意しておくとよいでしょう。

また、スロークエリログはpt-query-digestを利用することでより細かな解析をすることができます。
pt-query-digestの導入手順は以下の記事に書いてあるので興味がある人はご覧になってください。

Percona Toolkitをインストールし、pt-query-digestでスロークエリログを解析する手順

2021年6月13日

この記事がいいなと思いましたらツイッター(@nishina555)のフォローもよろしくお願いします！