表示速度を早くしたい。データベースサーバの負荷を軽くしたい。

そんなときに役に立つのがスロークエリログです。スロークエリログはその名の通り、遅いクエリを検出してログに出力してくれる機能です。

スロークエリログで遅いクエリをピックアップして、Explainを使いながらクエリやインデックスのチューニングしていく。そんな使い方をします。

設定確認方法

まずは、スロークエリが設定されているかどうかを確認します。mysqlコマンドから「show variables」コマンドを使いましょう。

mysql> show variables like 'slow_query%';
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_query_log      | OFF                                  |
| slow_query_log_file | /var/lib/mysql/slow.log |
+---------------------+--------------------------------------+
2 rows in set (0.00 sec)

mysql> show variables like 'long%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

それぞれのパラメータの意味は次の通りです。

設定方法

デフォルトでは、無効になっているので有効にしてみましょう。（MySQL5.7系を使って検証しています）

ここでは、1秒以上時間がかかったクエリを、「/var/lib/mysql/slow.log」へ出力するケースを考えてみます。

my.cnfに記載するときは、次の設定を[mysqld]の下に記載し、再起動させます。

• slow_query_log=1
• slow_query_log_file=’/var/lib/mysql/slow.log’
• long_query_time=1

一時的に設定を反映させたい場合は、下記コマンドでも構いません。

• set global slow_query_log=1;
• set global slow_query_log_file=’/var/lib/mysql/slow.log’;
• set global long_query_time=1;

正常に設定が反映されたか確認してみると次のようになっているはずです。

mysql> show variables like 'slow_query%';
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_query_log      | ON                      |
| slow_query_log_file | /var/lib/mysql/slow.log |
+---------------------+-------------------------+
2 rows in set (0.00 sec)

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

set globalで設定変更した場合、long_query_timeの値が反映されていないことがあります。そのときは、一旦exitしてから再接続して確認してみましょう。

ログの見方

スロークエリを設定すると、次の内容のログファイルが出力されます。

 cat /var/lib/mysql/slow.log
/usr/sbin/mysqld, Version: 5.7.22-log (MySQL Community Server (GPL)). started with:
Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument

ためしに、「select sleep(2)」というSQLを実行してみると、次のようなログが出力されます。

# cat /var/lib/mysql/slow.log
/usr/sbin/mysqld, Version: 5.7.22-log (MySQL Community Server (GPL)). started with:
Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2018-05-30T23:19:17.203966+09:00
# User@Host: root[root] @ localhost []  Id:     3
# Query_time: 2.000628  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1527689957;
select sleep(2);

もし、Timeの時刻がUTC表記になっている場合は、my.cnfに次の行を追加し反映させます。

• log_timestamps=SYSTEM

主要な項目について説明していきます。

豆知識

Timeが示す時間はいつ時点のもの?

そのスロークエリが、いつからいつまで動作していたかを知ることが重要になるときがあります。

そんなときは、TimeとQuery_timeの情報を確認しましょう。

Timeに出力される時刻は、クエリの実行が完了しログ出力されるタイミングの時刻です。

つまり、クエリが発行された開始時刻を知りたい場合は、Timeの時刻からQuery_timeを引いて上げる必要があります。

ロック待ちのクエリはスロークエリに出力されるのか？

ロック待ちは「long_query_time」の算出時間に含まれません。

long_query_timeの設定が3秒の場合は次のようになります。

• 検知される：クエリ秒数：5秒、ロック待ち：1秒　(計6秒)
• 検知されない：クエリ秒数：1秒、ロック待ち：5秒　(計6秒)

検索だけでなく、更新系も出力されるの？

出力されます。

long_query_timeは1秒以下でも指定が可能？

指定可能です。0.1を指定すると、0.1秒を超えたものを出力します。

0を指定すると、すべてのクエリを出力します。

まとめ

MySQLの遅いクエリを確認するためには、スロークエリの利用が有効です。

状況把握のために、必ず設定しておきましょう。

実際の運用の現場では、膨大な数のスロークエリが発生する可能性があります。そこでスロークエリを効率的に集計するために「mysqldumpslow」コマンドを利用します。

「mysqldumpslow」コマンドについては、別途まとめようと思います。