MySQLで遅いSQLを探すなら、スロークエリログに一定時間を超えたSQLを残し、同じ形のSQLごとに集計します。1回が遅いSQLと、何度も動いて合計時間が大きくなるSQLの両方を見ると、次に調べる対象を決めやすくなります。
最初に押さえたいのは、slow_query_log = ONだけでは記録条件が揃わないことです。出力先、時間の閾値、調べた行数の条件を確認します。また、GLOBALの閾値を変えても、すでに接続しているアプリのSESSION値は変わりません。
以下はMySQL 8.4.11の独立した検証環境で実行した例です。短い待機SQLで記録を確認し、集計後に設定を元へ戻します。実際のDBで使うときは、ログを採る時間帯・容量・閲覧権限を決めてから進めてください。SQL本文に検索値などが含まれるため、生ログをそのまま外部へ共有しないようにします。
現在値を保存し、短時間だけFILE出力を有効にする
管理用のSQL接続で、次の順に実行します。この例はslow_query_logとgeneral_logがどちらもOFFの検証環境を前提としています。すでに収集している環境では、既存のログ運用と調査担当を確認し、その設定を一律に置き換えないでください。
log_outputはgeneral logとslow logで共有する設定です。general logが稼働中にFILEへ変更すると、そちらの出力先にも影響します。出力先の関係はMySQL公式のログ出力先の説明で確認できます。
まず現在値を表示し、結果を手元の記録にも残します。続く@old_...は、同じ接続で元へ戻すための保存値です。接続を閉じると消えるので、復元が終わるまでこの接続を保ちます。
-- Run in one admin connection. Keep the displayed values outside the session too.
SELECT @@hostname, VERSION(), CONNECTION_ID();
SELECT @@GLOBAL.slow_query_log, @@GLOBAL.log_output,
@@GLOBAL.slow_query_log_file, @@GLOBAL.long_query_time,
@@SESSION.long_query_time, @@GLOBAL.min_examined_row_limit,
@@SESSION.min_examined_row_limit,
@@GLOBAL.log_queries_not_using_indexes, @@GLOBAL.general_log;
SET @old_slow = @@GLOBAL.slow_query_log;
SET @old_output = @@GLOBAL.log_output;
SET @old_global_time = @@GLOBAL.long_query_time;
SET @old_session_time = @@SESSION.long_query_time;
SET @old_global_rows = @@GLOBAL.min_examined_row_limit;
SET @old_session_rows = @@SESSION.min_examined_row_limit;
SET @old_no_index = @@GLOBAL.log_queries_not_using_indexes;
-- Lab precondition: slow_query_log=OFF and general_log=OFF.
-- Retain the existing slow_query_log_file path.
SET GLOBAL log_output = 'FILE';
SET GLOBAL long_query_time = 0.05;
SET GLOBAL min_examined_row_limit = 0;
SET GLOBAL log_queries_not_using_indexes = OFF;
SET GLOBAL slow_query_log = ON;
-- GLOBAL changes do not update this existing connection.
SELECT @@GLOBAL.long_query_time, @@SESSION.long_query_time;
SET SESSION long_query_time = 0.05;
SET SESSION min_examined_row_limit = 0;
SELECT SLEEP(0.12) AS frequent;
SELECT SLEEP(0.12) AS frequent;
SELECT SLEEP(0.12) AS frequent;
SELECT SLEEP(0.25) AS occasional;0.05秒は、この短い再現用の値です。本番でそのまま採用するとログ量が増えるため、アプリの応答目標と負荷に合わせて決めます。long_query_timeの既定値は10秒です。GLOBAL値の変更には、SYSTEM_VARIABLES_ADMINなどの管理権限が必要です。
この例では既存のslow_query_log_fileを使い、ファイル名を変更していません。表示されたパスはMySQLが動くサーバー側のパスです。SQLクライアントを起動した手元のPCとは限りません。権限がなく設定を変更できない環境では、管理者やマネージドDBのログ機能で取得します。
ログが出ないときは、接続ごとの閾値と走査行数を見る
検証ではGLOBALを0.05秒へ変更した直後も、同じ接続のSESSIONは10秒のままでした。その接続へ明示的にSET SESSION long_query_time = 0.05;を実行すると、0.12秒の待機SQLが記録されました。変更後に作った新しい接続も、GLOBALの0.05秒を引き継いで記録できています。
接続プールを使うアプリでは、前から開いている接続が残ります。SQLエディタで自分のSESSIONだけを変えても、アプリ接続の閾値は変わりません。アプリ側で使っている接続の値を確かめ、必要に応じて接続を作り直すなど、運用に合う反映方法を選びます。GLOBALとSESSIONの反映範囲も参照してください。
| 確認する項目 | ログが出ない理由の例 | 次の確認 |
|---|---|---|
slow_query_log |
OFFになっている | 対象サーバーと有効状態を確認 |
log_output |
TABLEのみ、またはNONE | FILEを読んでよい設定か確認 |
@@SESSION.long_query_time |
既存接続に以前の閾値が残る | SQLを実行する接続自身で確認 |
@@SESSION.min_examined_row_limit |
調べた行数が条件に届かない | 時間だけで収集する検証では0を使う |
slow_query_log_file |
違うサーバーやパスを見ている | 実値とMySQLの書き込み権限を確認 |
| SQLの完了 | まだ実行中でログへ出ていない | 完了後の記録と、実行中の待機調査を分ける |
min_examined_row_limitは、SQLが調べた行数の下限です。今回のSELECT SLEEP(...)は生ログ上でRows_examined: 1となり、この下限を2にすると記録されず、0に戻すと記録されました。テーブルを直接読まない文だから常に0行、と推測せず、実際のログで確認します。
log_queries_not_using_indexesをONにすると、行の検索にインデックスを使わないSQLも収集対象になります。検証では、時間の閾値を100秒にしても、3行を調べる短い検索が記録されました。まず遅いSQLを探したいならOFFから始め、インデックス未使用の調査が必要になったときに対象を広げると、目的とログ量を揃えやすくなります。
生ログの1件から、時間・返却行数・走査行数を読む
ログファイルを読める環境で、slow_query_log_fileの実値を指定します。次のパスは差し替え用です。Docker内にあるファイルなら、そのコンテナ内で確認するか、調査用に取得したコピーを読みます。
tail -n 40 /path/to/mysql-slow.log以下は検証ログから、時間とSQLの行を抜き出したものです。待機時間を作るためのSLEEPであり、インデックス改善の効果を測った結果ではありません。
# Query_time: 0.120272 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1789183197;
SELECT SLEEP(0.12) AS frequent;| 項目 | 読み取る内容 |
|---|---|
Query_time |
SQLの実行時間。単位は秒 |
Lock_time |
ロック取得に要した時間。これだけで全種類の待機を説明できるとは考えない |
Rows_sent |
クライアントへ返した行数 |
Rows_examined |
サーバー層で調べた行数。ストレージエンジン内部の処理をすべて数えた値ではない |
仕様と出力項目はMySQL公式のslow query logに記載されています。返した行数に対して調べた行数が多ければ、条件や実行計画を確認する手掛かりになります。ただし、集計処理などでは多くの行を読むこと自体が必要な場合もあり、この比率だけでインデックスを追加する判断はできません。
ログは実行を終え、ロックを解放した後に書かれます。今まさに止まっているSQLやロックを持つ接続を探したい場合は、ロック待ち・デッドロックの確認方法へ進みます。
mysqldumpslowで、合計時間・回数・平均時間を見比べる
収集範囲を決めたログのコピーを、mysqldumpslowで集計します。このコマンドは、数値や文字列が違うだけのSQLをまとめて表示します。mysqldumpとは別のツールです。見つからない場合は、使用中のMySQL配布パッケージに含まれるかを確認してください。
# ログに残ったSQLの合計時間が大きい順
mysqldumpslow -l -s t /path/to/mysql-slow.log
# ログに残った回数が多い順
mysqldumpslow -l -s c /path/to/mysql-slow.log
# 1回あたりの平均時間が大きい順
mysqldumpslow -l -s at /path/to/mysql-slow.log-s tは合計時間、-s cは記録回数、-s atは平均時間の並べ替えです。ここでは-lも指定し、Query_timeからLock_timeを差し引かずに集計しています。オプションの定義はmysqldumpslowの公式リファレンスで確認できます。
先ほどの4回のSQLだけを含むログを集計すると、次のようになりました。Time=の直後は平均秒数、括弧内は合計秒数です。括弧内は整数表示のため、1秒未満の合計は0sに見えます。
Count: 3 Time=0.12s (0s) Lock=0.00s (0s) Rows=1.0 (3), root[root]@localhost
SELECT SLEEP(N.N) AS frequent
Count: 1 Time=0.25s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost
SELECT SLEEP(N.N) AS occasional合計時間順ではfrequentが先、平均時間順ではoccasionalが先になります。3回動く0.12秒のSQLは合計約0.36秒なので、1回だけ動く約0.25秒のSQLより上に来るわけです。
Countはログに残った回数であり、アプリ全体で実行された総回数ではありません。閾値より速かった実行は含まれないため、頻度を比較するときは収集期間と設定も揃えます。また、集計のRowsは返却行数に基づく値です。走査行数のRows_examinedを確認したいときは、対応する生ログへ戻ります。
今回使った最小構成のDockerイメージには集計ツールが入っていなかったため、検証では同じMySQL 8.4.11の公式ソースにあるmysqldumpslowをPerlで実行しました。サーバーで採ったログを、ツールのある調査用PCで集計する形でも構いません。
確認が終わったら、同じ接続で元の設定へ戻す
収集終了時は、冒頭で保存した値を表示します。どれかがNULLなら、そのまま復元SQLを流さず止めてください。別の接続を開いてしまった可能性があります。その場合は手元に記録した元の値を使い、管理対象の設定と照合して戻します。
-- Same connection as capture.sql; inspect saved values before changing anything.
SELECT @old_slow, @old_output, @old_global_time, @old_session_time,
@old_global_rows, @old_session_rows, @old_no_index;
-- If a saved value is NULL, stop and use the separately recorded original values.
SET GLOBAL slow_query_log = OFF;
SET GLOBAL long_query_time = @old_global_time;
SET GLOBAL min_examined_row_limit = @old_global_rows;
SET GLOBAL log_queries_not_using_indexes = @old_no_index;
SET GLOBAL log_output = @old_output;
SET SESSION long_query_time = @old_session_time;
SET SESSION min_examined_row_limit = @old_session_rows;
SET GLOBAL slow_query_log = @old_slow;
SELECT @@GLOBAL.slow_query_log, @@GLOBAL.log_output,
@@GLOBAL.long_query_time, @@SESSION.long_query_time,
@@GLOBAL.min_examined_row_limit, @@SESSION.min_examined_row_limit,
@@GLOBAL.log_queries_not_using_indexes;この例の開始状態はslow logがOFFなので、最後もOFFへ戻ります。ログの停止と、過去のログの削除は別です。残ったファイルは閲覧権限・保管期間・ローテーションの方針に従って扱います。
今回の検証では、GLOBALと管理接続のSESSION値が開始前と一致し、復元後に追加した待機SQLでログが増えないことまで確認しました。調査中に作られたほかの接続には、その接続自身のSESSION値が残る点にも注意してください。継続運用へ戻す際は、アプリ側の接続管理も確認します。
次に調べるSQLを、収集条件と一緒に記録する
集計を見てすぐ設定を増やすより、調査対象を1つ選び、生ログと実行計画を照合できる状態にします。次の表を埋めると、後日の比較で閾値や収集時間が違っていた、という取り違えを防げます。
| 記録項目 | 残すこと |
|---|---|
| 収集条件 | サーバー、開始・終了時刻、時間と走査行数の閾値、インデックス未使用SQLの扱い |
| SQLの形 | 対象テーブルと条件。共有用の値は機密情報を除く |
| 優先度 | 記録回数、平均時間、合計時間と、利用者への影響 |
| 生ログの手掛かり | 代表例のQuery_time、Rows_sent、Rows_examined |
| 次の調査 | 実行計画、取得列、呼び出し回数など、確かめる対象を1つ選ぶ |
| 比較 | 変更後も同じ条件で採った結果と、アプリの応答時間 |
継続して収集するなら、一時調査を終えてから、保存容量とローテーションを含めた設定を決めます。起動時の設定ファイルの[mysqld]で管理する方法と、SET PERSISTで永続化する方法があります。両方へ無計画に書かず、現在の管理方法に揃えてください。変数の確認・変更の基本はMySQLのシステム変数で確認できます。
SQLの送信履歴そのものを見たい場合は、general logとDBeaverのQuery Managerが使えます。性能調査では、今回選んだSQLの読み取り量や呼び出し方を確認し、同じ条件で再測定するところへ進めましょう。