1.スロークエリーログ(sloq_query_log)とは

スロークエリーログとは、設定された閾値を超える時間がかかってしまった遅いクエリを記録しておく機能です。

スロークエリーログを確認することで、実行に長い時間がかかっている最適化の候補となるクエリを見つける事ができます。

2.使用するための準備

2-1.スロークエリーログの有効化

デフォルトではスロークエリーログが無効になっているため、機能を有効化しないとログが出力されません。

使用するにはMySQLのグローバル変数slow_query_logをONに変更するだけです。

mysql> SET GLOBAL slow_query_log = 'ON';

mysql> SHOW GLOBAL variables LIKE 'slow_query_log';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+

2-2.その他のパラメータ

その他にもスロークエリーログに関係するパラメータがいくつかあるので、使用頻度が高そうなものを以下に記載します。

以下のいずれも上記のslow_query_log同様にSET GLOBAL <パラメータ名> = <値>の形式で変更する事ができます！

パラメータ名	説明
slow_query_log	スロークエリーログの有効/無効を指定する
long_query_time	スロークエリーログに出力する時間の閾値を指定する設定した時間を超えるクエリがスロークエリーログとして出力される
min_examined_row_limit	スロークエリーログに出力するクエリが検査した最低行数を指定するクエリが検査した行数がこの値以下であれば、時間がかかっていてもスロークエリーログには出力されない
slow_query_log_file	スロークエリーログが吐き出されるファイルを指定する
log_slow_admin_statements	管理ステートメント（ALTER TABLE、ANALYZE TABLE、CHECK TABLE、CREATE INDEX、DROP INDEX、OPTIMIZE TABLE）をログに記録するかどうかを指定する
log_queries_not_using_indexes	ONにするとインデックスを使用していないクエリを記録するスロークエリーログが膨大になる事があるので注意!
log_output	ログの出力形式を選択する「FILE」:ログファイルに出力「TABLE」:スロークエリーログを記録するテーブルに出力「NONE」:いずれにも出力しない

3.ログの出力〜確認

3-1.検証用のテーブル

MySQL公式が提供しているemployeesテーブルを使用して、SQLを実行してみます。
https://dev.mysql.com/doc/employee/en/

3-2.検証用の設定値

今回は確認用に以下のようなバージョン・設定値にしました。

mysql> select version();
+-----------+
| version() |
+-----------+
| 5.7.24    |
+-----------+

+---------------------------------+---------------------------------------------+
| Variable_name                   | Value                                       |
+---------------------------------+---------------------------------------------+
| slow_query_log                  | ON                                          |
| long_query_time                 | 0.100000                                    |
| min_examined_row_limit          | 0                                           |
| slow_query_log_file             | /var/lib/mysql/a3b7444a1e1e-slow.log        |
| log_slow_admin_statements       | OFF                                         |
| log_queries_not_using_indexes   | OFF                                         |
| log_output                      | FILE                                        |
+---------------------------------+---------------------------------------------+

3-3.クエリの実行

スロークエリーログとして吐き出されることを確認するために0.1秒以上かかるクエリを実行してみます。

-- ①
mysql> select emp_no, birth_date, hire_date, concat(first_name, ' ', last_name) as emp_name from employees where birth_date >= '1965-01-01' and hire_date >= '1990-01-01' and gender = 'M';
535 rows in set (0.11 sec)

-- ②
mysql> select count(*) from salaries where salary >= 10000;
1 row in set (0.41 sec)

-- ③
mysql> select count(*) from titles where title LIKE '%r';
1 row in set (0.11 sec)

3-4.結果の確認（ログファイル目視）

吐き出されたログファイルを確認してみます。

クエリの実行されたタイムスタンプ・回数・平均実行時間・テーブルをロックした時間・クエリの内容などが出力されている事が確認できます。

下記は適宜改行を入れていますが、実際はもっと詰まって出力されるので結構見づらく感じます...。

cat a3b7444a1e1e-slow.log

-- ①
# Time: 2022-01-07T07:53:50.687551Z
# User@Host: root[root] @ localhost []  Id:    10
# Query_time: 0.113801  Lock_time: 0.000335 Rows_sent: 535  Rows_examined: 300025
SET timestamp=1641542030;
select emp_no, birth_date, hire_date, concat(first_name, ' ', last_name) as emp_name from employees where birth_date >= '1965-01-01' and hire_date >= '1990-01-01' and gender = 'M';

-- ②
# Time: 2022-01-07T07:54:07.943312Z
# User@Host: root[root] @ localhost []  Id:    10
# Query_time: 0.410568  Lock_time: 0.000513 Rows_sent: 1  Rows_examined: 2844047
SET timestamp=1641542047;
select count(*) from salaries where salary >= 10000;

-- ③
# Time: 2022-01-07T07:54:16.358159Z
# User@Host: root[root] @ localhost []  Id:    10
# Query_time: 0.108477  Lock_time: 0.000733 Rows_sent: 1  Rows_examined: 443308
SET timestamp=1641542056;
select count(*) from titles where title LIKE '%r';

3-5.結果の確認（mysqldumpslow）

mysqldumpslowコマンドは3-4で確認したスロークエリーログファイルを解析して内容のサマリーを出力してくれます。

サマリでは条件に指定した数字は'N'、文字列は'S'として抽象化され、条件に指定した数字や文字列だけが異なるクエリは同じものとしてまとめられます。

この時点でログファイルを直接開いた結果よりはだいぶ見やすく感じます！

> mysqldumpslow a3b7444a1e1e-slow.log

-- ①
Count: 1  Time=0.11s (0s)  Lock=0.00s (0s)  Rows=535.0 (535), root[root]@localhost
  select emp_no, birth_date, hire_date, concat(first_name, 'S', last_name) as emp_name from employees where birth_date >= 'S' and hire_date >= 'S' and gender = 'S'

-- ②
Count: 3  Time=0.40s (1s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select count(*) from salaries where salary >= N

-- ③
Count: 3  Time=0.36s (1s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select count(*) from titles where title LIKE 'S'

3-5-1.mysqldumpslowのオプション

mysqldumpslowコマンドに以下のオプションを指定することで、出力を加工する事ができます。

オプション名	説明
-a	数字、文字列を抽象化しない
-g pattern	パターンに一致するステートメントのみを出力
-r	ソート順序を逆転
-s sort_type	出力のソート方法 t、at: クエリー時間または平均クエリー時間でソート l、al: ロック時間または平均ロック時間でソート r、ar: 送信行数または平均送信行数でソート c: カウントでソート
-t count	最初から指定された数だけのクエリーのみ表示

3-5-2.オプション使用例

-- 'salary'という文言を含むスロークエリを特定する
mysqldumpslow -g salary a3b7444a1e1e-slow.log

-- 最も実行されているスロークエリを特定する （出現回数順にソートして、最初の1個だけを表示する）
mysqldumpslow -s c -t 1 a3b7444a1e1e-slow.log

-- 最も時間がかかっているスロークエリを特定する （実行時間順にソートして、最初の1個だけを表示する）
mysqldumpslow -s t -t 1 a3b7444a1e1e-slow.log

4.ログが出力されない場合のチェックリスト

実行しているクエリーは管理ステートメントではないか？
- 管理ステートメントを出力したい場合log_slow_admin_statements が有効になっているか？
クエリー実行にlong_query_time秒かかっているか?
クエリーはmin_examined_row_limit行以上を検査しているか？
実行したクエリーがクエリーキャッシュによって処理されていないか？
テーブルに2行以上存在するか？
- 0行や1行のテーブルに対してはインデックスがあることのメリットがないこと（改善の余地がない）から、そういったテーブルに実施されたクエリーはスロークエリーログに書き込まれない