MySQLのスロークエリログを有効にする ― long_query_timeが効かないとき、mysqldumpslowで集計

※この記事にはアフィリエイト広告（プロモーション）が含まれます。

遅い SQL を探すには、まずスロークエリログを有効にします。この記事の出力は MySQL 8.4.11（Ubuntu 26.04 の標準パッケージ）で採りました。

まず見る（結論）

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 1;      -- 1秒を超えた文を記録（既定は 10 秒）
SHOW GLOBAL VARIABLES LIKE 'slow_query_log_file';

• SET GLOBAL long_query_time は、その後に接続したセッションから効く。設定した接続のまま試しても記録されない
• SET GLOBAL は再起動で消える。残すなら SET PERSIST か設定ファイル
• Ubuntu の既定の出力先は /var/lib/mysql/<ホスト名>-slow.log

既定値

SHOW GLOBAL VARIABLES WHERE Variable_name IN ('slow_query_log', 'slow_query_log_file', 'long_query_time',
  'log_output', 'log_queries_not_using_indexes', 'min_examined_row_limit');
+-------------------------------+---------------------------------+
| Variable_name                 | Value                           |
+-------------------------------+---------------------------------+
| log_output                    | FILE                            |
| log_queries_not_using_indexes | OFF                             |
| long_query_time               | 10.000000                       |
| min_examined_row_limit        | 0                               |
| slow_query_log                | OFF                             |
| slow_query_log_file           | /var/lib/mysql/dbhost-slow.log |
+-------------------------------+---------------------------------+

Ubuntu の /etc/mysql/mysql.conf.d/mysqld.cnf には、slow_query_log と slow_query_log_file = /var/log/mysql/mysql-slow.log がコメントアウトされた状態で入っていました。

SET GLOBAL した接続には効かない

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 1;
SELECT @@SESSION.long_query_time, @@GLOBAL.long_query_time;
+---------------------------+--------------------------+
| @@SESSION.long_query_time | @@GLOBAL.long_query_time |
+---------------------------+--------------------------+
|                 10.000000 |                 1.000000 |
+---------------------------+--------------------------+
SELECT SLEEP(1.5);

この SLEEP(1.5) はログに出ませんでした。long_query_time はセッションごとの値で、接続したときにグローバルの値をコピーします。

接続し直して同じ SELECT SLEEP(1.5) を流すと記録されました。アプリケーションの接続プールのように前から繋がっている接続も、繋ぎ直すまで元の値のままです。今の接続だけで試すなら SET SESSION long_query_time = 1; も実行します。

ログの読み方

# Time: 2026-10-29T02:53:47.125785Z
# User@Host: root[root] @ localhost []  Id:    59
# Query_time: 0.034590  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 300000
SET timestamp=1793242427;
SELECT COUNT(*) FROM orders WHERE amount > 500;

Rows_sent 1 に対して Rows_examined 300000 のように差が大きい文は、索引で絞り込めていない可能性があります。EXPLAIN で確かめます。

索引を使わない文も記録する

log_queries_not_using_indexes = ON にすると、long_query_time 未満でも索引を使わない文が記録されます。long_query_time を 10 秒にしたまま3つの文を流したところ、索引の無い amount で絞った SELECT id FROM orders WHERE amount = 10.5 LIMIT 1（0.0003 秒）だけが記録されました。索引で引いた文と、索引の無い小さな表の COUNT(*) は出ませんでした。

mysqldumpslow で集計する

$ mysqldumpslow -s t /var/lib/mysql/dbhost-slow.log
Count: 3  Time=1.20s (3s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  SELECT SLEEP(N.N)

Count: 1  Time=0.03s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  SELECT COUNT(*) FROM orders WHERE amount > N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=30.0 (60), root[root]@localhost
  SELECT * FROM orders WHERE customer_id = N

数値は N に置き換えられ、同じ形の文がまとめて数えられます。Time=1.20s (3s) は平均と合計です。-s t は合計時間順、-s c は回数順、-t 3 で上位3件に絞れます。Ubuntu では /usr/bin/mysqldumpslow に入っていました。

表に出す（log_output = ‘TABLE’）

SET GLOBAL log_output = 'TABLE';
SELECT start_time, query_time, rows_examined, CONVERT(sql_text USING utf8mb4) AS sql_text FROM mysql.slow_log;
+----------------------------+-----------------+---------------+-------------------------------+
| start_time                 | query_time      | rows_examined | sql_text                      |
+----------------------------+-----------------+---------------+-------------------------------+
| 2026-10-29 11:53:52.096786 | 00:00:01.200427 |             1 | SELECT SLEEP(1.2) AS to_table |
+----------------------------+-----------------+---------------+-------------------------------+

出力先を変える

SET GLOBAL slow_query_log_file = '/var/log/mysql/mysql-slow.log';     -- 成功
SET GLOBAL slow_query_log_file = '/root/fsv-slow.log';
ERROR 1231 (42000): Variable 'slow_query_log_file' can't be set to the value of '/root/fsv-slow.log'

存在しないディレクトリ（/nosuchdir/）も同じ ERROR 1231 で、どちらも設定は元のままでした。/tmp/ には作れました。

再起動しても残す

SET GLOBAL で有効にした後に systemctl restart mysql すると、slow_query_log は OFF、long_query_time は 10 に戻りました。

SET PERSIST

SET PERSIST slow_query_log = ON;
SET PERSIST long_query_time = 2;

再起動後も ON と 2 のままでした。値は /var/lib/mysql/mysqld-auto.cnf に JSON で書かれます。取り消しは RESET PERSIST slow_query_log; です。

設定ファイル

# /etc/mysql/mysql.conf.d/zz-slow.cnf
[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1

再起動後に3つとも反映されていました。書き間違いがあると起動しません。試しに long_query_time = 1s と書いて再起動しました。

$ sudo systemctl restart mysql
Job for mysql.service failed because the control process exited with error code.
$ journalctl -u mysql
... [ERROR] [MY-000084] [Server] Invalid decimal value for option 'long_query_time'.
... [ERROR] [MY-000077] [Server] /usr/sbin/mysqld: Error while setting value '1s' to 'long_query_time'.
... mysql.service: Start request repeated too quickly.

起動しない理由は journalctl に出ており、/var/log/mysql/error.log には出ていませんでした。再起動の前に sudo mysqld --validate-config --user=mysql を実行すると、同じエラーが終了コード 1 で出ます。正しい設定なら何も出ず 0 です。

設定を直した後、sudo systemctl reset-failed mysql を実行してから sudo systemctl start mysql で起動しました。

権限

GRANT ALL ON fsv.* だけのユーザーが SET GLOBAL slow_query_log = ON; を実行すると、ERROR 1227 (42000): Access denied; you need (at least one of) the SUPER or SYSTEM_VARIABLES_ADMIN privilege(s) for this operation が返りました。SET SESSION long_query_time = 0; は同じユーザーで通りました。自分のセッションの文だけをすべて記録させることはできます（ログ自体が有効になっている必要があります）。

関連: MySQLのEXPLAINの見方 ／ MySQLの「Lock wait timeout exceeded」 ／ MySQLの「Too many connections」