MySQLのスロークエリについてのまとめ

   2020/05/12

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

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

スロークエリログで遅いクエリをピックアップして、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)

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

パラメータ
slow_query_log 0(OFF),1(ON)
slow_query_log_file 出力ファイル名
long_query_time 検知秒数

設定方法

デフォルトでは、無効になっているので有効にしてみましょう。(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 ログ出力された日時が出力されます
User@Host クエリの発行元の情報が出力されます
Id 接続元のコネクション識別子です
Query_time クエリ発行にかかった時間です
Lock_time ロック待ちの時間です
Rows_sent 取得行数です
Rows_examined 探索対象行数です

豆知識

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」コマンドについては、別途まとめようと思います。

  • このエントリーをはてなブックマークに追加
  • Pocket

この記事へのコメントはこちら

メールアドレスは公開されませんのでご安心ください。
また、* が付いている欄は必須項目となりますので、必ずご記入をお願いします。

内容に問題なければ、下記の「コメント送信」ボタンを押してください。