再現性のあるスロークエリーには「SHOW PROFILE」を試してみよう

MySQLの組み込みプロファイラー

SHOW PROFILEステートメントはMySQLサーバー組み込みのプロファイラーから情報を取り出すためのステートメントです。細かいことを言と、これが利用可能かどうかはビルドオプション（cmake -DENABLED_PROFILING=ON）で決まりますが、少なくともOracleが配布しているバイナリーではこのオプションが有効な状態でビルドされているため、ほとんどの環境で利用できるでしょう。

プロファイラーというと小難しく思えますが、「そのクエリーが実行されていた期間、どのStatus（SHOW PROCESSLISTで"State"と表示されているもの）にどのくらいの時間かかったか」を表示してくれるもので、セッション単位でオンラインに有効・無効を切り替えられるため、身構える必要は全くありません。まずはその内容を確認するため、試しに具体的なステートメントを実行していきます。

SHOW PROFILEの利用方法

プロファイラーの有効・無効はprofilingというセッション変数で制御されます。SET SESSION profiling = 1またはSET @@profiling = 1でプロファイラーが有効になります（どちらも同じ意味）。セッション変数なので、このステートメントを実行した以外のスレッドには何の影響も及ぼしません（プロファイラーは有効にならない）。MySQL 5.6以降ではこのプロファイラーは非推奨（将来のリリースで機能が削除される予定）となっており、SETステートメントを実行した際にワーニングが出ますが、今のところ（MySQL 5.7.13現在）利用には問題ないので、そのまま見ていきましょう（なお、 ドキュメント 上では代替手段としてパフォーマンススキーマが案内されている）。

mysql> SET @@profiling= 1;
Query OK, 0 rows affected, 1 warning (0.01 sec)

mysql> SHOW WARNINGS;
+---------+------+----------------------------------------------------------------------+
| Level   | Code | Message                                                              |
+---------+------+----------------------------------------------------------------------+
| Warning | 1287 | '@@profiling' is deprecated and will be removed in a future release. |
+---------+------+----------------------------------------------------------------------+
1 row in set (0.00 sec)

profiling変数を有効にしたら、プロファイルしたいクエリーを実行してみてください。実行したら、他のステートメントを叩く前にSHOW PROFILEを実行します。

mysql> SHOW PROFILE;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000206 |
| checking permissions | 0.000024 |
| Opening tables       | 0.000039 |
| init                 | 0.000089 |
| System lock          | 0.000027 |
| optimizing           | 0.000037 |
| statistics           | 0.000245 |
| preparing            | 0.000058 |
| Creating tmp table   | 0.000119 |
| Sorting result       | 0.000023 |
| executing            | 0.000019 |
| Sending data         | 2.619037 |
| Creating sort index  | 0.000821 |
| end                  | 0.000014 |
| removing tmp table   | 0.000017 |
| end                  | 0.000013 |
| query end            | 0.000015 |
| closing tables       | 0.000022 |
| freeing items        | 0.000028 |
| logging slow query   | 0.000109 |
| cleaning up          | 0.000013 |
+----------------------+----------+
21 rows in set (0.00 sec)

クエリーが処理される中で通過した"Status"と、かかった時間の"Duration"が出力されます。

例えば、上記の例では"Sending data"に時間がかかっています。"Sending data"はストレージエンジンからデータをフェッチする時のステータスです。おそらく、インデックスが使えていないなどでフェッチする行を最小化できていないために時間がかかっているのでしょう。よく見ると"Creating tmp table"も出力されており、テンポラリーテーブルを利用していることがわかります。

テンポラリーテーブルが大きくなりすぎてディスク上にテンポラリーテーブルを作成した場合（MySQL 5.6以前はMyISAM、5.7ではデフォルトでInnoDBが利用される）は"converting HEAP to .."も合わせて表示されるため、表示されていない今回の例ではテンポラリーテーブルはメモリー上で収まっていることがわかります。

それでは、次のような出力があった場合はどうでしょうか。

mysql> SHOW PROFILE;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000132 |
| Waiting for query cache lock   | 0.000006 |
| checking query cache for query | 0.003187 |
| checking permissions           | 0.000010 |
| checking permissions           | 0.000044 |
| Opening tables                 | 0.000040 |
| System lock                    | 0.000015 |
| init                           | 0.001391 |
| optimizing                     | 0.000411 |
| statistics                     | 0.000043 |
| preparing                      | 0.000021 |
| executing                      | 0.000003 |
| Sending data                   | 0.000313 |
| optimizing                     | 0.000017 |
| statistics                     | 0.000364 |
| preparing                      | 0.000335 |
| executing                      | 0.000006 |
| Sending data                   | 0.000349 |
| executing                      | 0.000005 |
| Sending data                   | 0.001004 |
| executing                      | 0.000004 |
| Sending data                   | 0.000027 |
| executing                      | 0.000002 |
| Sending data                   | 0.000018 |
| executing                      | 0.000002 |
| Sending data                   | 0.000009 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000016 |
| executing                      | 0.000001 |
| Sending data                   | 0.000010 |
| executing                      | 0.000001 |
| Sending data                   | 0.000020 |
| executing                      | 0.000002 |
| Sending data                   | 0.000010 |
| executing                      | 0.000002 |
| Sending data                   | 0.000010 |
| executing                      | 0.000002 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000005 |
| executing                      | 0.000001 |
| Sending data                   | 0.000010 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000003 |
| executing                      | 0.000001 |
| Sending data                   | 0.000008 |
| executing                      | 0.000002 |
| Sending data                   | 0.000008 |
| executing                      | 0.000001 |
| Sending data                   | 0.000004 |
| executing                      | 0.000001 |
| Sending data                   | 0.000007 |
| executing                      | 0.000001 |
| Sending data                   | 0.000009 |
| executing                      | 0.000001 |
| Sending data                   | 0.000021 |
| executing                      | 0.000001 |
| Sending data                   | 0.000016 |
| end                            | 0.000004 |
| query end                      | 0.000008 |
| closing tables                 | 0.000009 |
| freeing items                  | 0.000214 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000004 |
+--------------------------------+----------+
82 rows in set (0.01 sec)

"Sending data"（ストレージエンジンからのデータフェッチ）と"executing"（オプティマイザーが決定した実行計画の通りにデータをフェッチするエグゼキューターの動作）を数十回も繰り返しています。ご存知の方はわかると思いますが、これは相関サブクエリーの場合のプロファイラーの出力です（外側のクエリーでマッチした行ごとに内側のクエリーを実行するため、このような表示になる）。

クエリーの直後にSHOW PROFILEを実行できなかった場合、SHOW PROFILES（複数形）ステートメントを実行することで、ヒストリー（profiling_history_sizeで設定可能）に残っているクエリーのプロファイルを一覧できます。

mysql> SHOW PROFILES;
+----------+-------------+-------------------------------------------------------------------------------+
| Query_ID | Duration    | Query                                                                         |
+----------+-------------+-------------------------------------------------------------------------------+
|        1 |  7.56061200 | SELECT * FROM t1 WHERE val IN (SELECT val FROM t2 WHERE num BETWEEN 1 AND 10) |
|        2 |  8.00373925 | DELETE FROM t1 WHERE num > 1000                                               |
|        3 |  1.05841250 | DELETE FROM t1 WHERE num > 100                                                |
|        4 | 33.97938100 | DELETE FROM t2 WHERE num > 100                                                |
|        5 |  1.09654200 | DELETE FROM t2 WHERE num > 40                                                 |
|        6 |  0.03032175 | DELETE FROM t1 WHERE num > 40                                                 |
|        7 |  0.00410725 | explain SELECT * FROM t2 JOIN t1 USING(val) WHERE t2.num = 1                  |
|        8 |  0.01773500 | SELECT * FROM t1 WHERE val IN (SELECT val FROM t2 WHERE num BETWEEN 1 AND 10) |
|        9 |  0.02148750 | DELETE FROM t1 WHERE num > 30                                                 |
|       10 |  0.27967925 | DELETE FROM t2 WHERE num > 30                                                 |
|       11 |  0.00826075 | SELECT * FROM t1 WHERE val IN (SELECT val FROM t2 WHERE num BETWEEN 1 AND 10) |
+----------+-------------+-------------------------------------------------------------------------------+
11 rows in set (0.01 sec)

例えば、uery_ID 4番のDELETE FROM t2 WHERE num > 100のプロファイルを見たい場合、SHOW PROFILEステートメントにFOR QUERY 4を渡します。

mysql> SHOW PROFILE FOR QUERY 4;
+------------------------------+-----------+
| Status                       | Duration  |
+------------------------------+-----------+
| starting                     |  0.007228 |
| checking permissions         |  0.000302 |
| Opening tables               |  0.001042 |
| System lock                  |  0.000030 |
| init                         |  0.006702 |
| updating                     | 33.930371 |
| end                          |  0.000923 |
| Waiting for query cache lock |  0.000013 |
| end                          |  0.002784 |
| query end                    |  0.024151 |
| closing tables               |  0.000430 |
| freeing items                |  0.000809 |
| logging slow query           |  0.000006 |
| logging slow query           |  0.004583 |
| cleaning up                  |  0.000009 |
+------------------------------+-----------+
15 rows in set (0.01 sec)

DELETEステートメントの"Status"は"updating"です。SHOW PROFILEにはいくつかの追加キーワードがあり、出力するカラムを増やすことができます。詳細はドキュメントで確認できます（ただし、筆者が調べた限りMEMORYキーワードはパースはされるものの処理は実装されていないようだった）。

SHOW PROFILEの使いどころ

SHOW PROFILEが有効なケースは、「EXPLAIN上問題ない（なさそうに見える）」「クエリーの遅さに再現性がある」際に有効な「場合があります」。それは、以下のような理由からです。

• EXPLAINの時点で明らかに悪そうなクエリーの場合はEXPLAINの結果からSQLのチューニングを実施した方が効率が良い
• 「実行したクエリーの所要時間を記録する」ものであるため、@@profilingをオンにした状態で遅さが再現できない場合は計測できない（そのため更新系のクエリーは計測しにくいのも実情）
• プロファイルを確認した結果、自明な結論が導かれることも多い（本当に1000万行フェッチする必要があるクエリーはまず間違いなく"Sending data"が大きくなる。「それは知ってるんだよ！」という気分になりますね）

「チューニングに銀の弾丸はない」とはいえ、SHOW PROFILEは銀の弾丸どころか相当ひねくれたニッチなツールです。筆者が常日頃SHOW PROFILEを利用するかと聞かれれば"No"と答えます。しかしEXPLAINや各種ステータス変数とは違った観点でクエリーを分析できるため、EXPLAINに詰まった（問題点がわからなかった）場合に次に利用するのはSHOW PROFILEかなと思います。

過去に、筆者がSHOW PROFILEの結果から問題の特定に至ったケースには以下のようなものがあります。

• "Waiting for query cache lock"（クエリーキャッシュロック、mysqld全体で1つしかロックがないため並列度が上がると容易にロック競合する） でクエリーが待たされているケース
• EXPLAIN上ではクエリーキャッシュは考慮されない。ひどい場合はSHOW PROCESSLISTでも確認できる
• 同じクエリーであるにも関わらず"Sending data"や"Opening tables"の値が大きくブレる場合はキャッシュミスヒットが疑える
• "Sending data"の場合、「1回目に実行した時は必ず遅く、2回目以降は必ず速い」というケースはこれに該当することがある。特にInnoDBの圧縮テーブルで発生しやすい（キャッシュミスヒットのオーバーヘッドが非常に大きい）
• "Opening tables"で時間がかかる場合は再現性がバラバラになる（テーブルキャッシュミスヒットは同時に実行されている他のクエリーに大きく依存するため）
• スロークエリーログがテーブル（mysql.slow_log）に出力されている場合、"logging slow query"の後にもう一度"Opening tables"と"System lock"が出力され、スローログの記録にかかった時間を見ることができる

performance_schemaでの利用法と相違点

冒頭でも説明しましたが、MySQL 5.6以降ではこのプロファイラーは非推奨（将来のリリースで機能が削除される予定）となっており、代替手段としてperformance_schemaが案内されています。SHOW PROFILEは個別のセッションに対するクエリー単位のプロファイラーであり、 performance_schemaはデフォルトで全てのセッションに対するイベント単位のプロファイラーです。MySQL 5.6以降ではデフォルトでperformance_schemaが有効になっていますが、サーバーのメモリー使用量に影響するため、明示的に無効化している場合もあるのではないでしょうか（その場合、当然ながらperformance_schemaをSHOW PROFILEの代替としては利用できない）。

また、performance_schemaを有効にしただけではSHOW PROFILEのようなクエリー内部のステータスの変遷は記録されません。performance_schemaが蓄積する情報の種類を増やしてあげる必要があります。まずはperformance_schema.setup_consumersのevents_stages_*とevents_statements_*（本質的にevents_statements_*は不要だが、これを有効にしないとプロファイル結果とSQLステートメントの紐付けができないため、プロファイラーとして利用するためにはこちらも有効にする必要がある）をENABLED = 'YES'に設定します。

mysql> SELECT * FROM performance_schema.setup_consumers;
+--------------------------------+---------+
| NAME                           | ENABLED |
+--------------------------------+---------+
| events_stages_current          | NO      |
| events_stages_history          | NO      |
| events_stages_history_long     | NO      |
| events_statements_current      | YES     |
| events_statements_history      | NO      |
| events_statements_history_long | NO      |
| events_waits_current           | NO      |
| events_waits_history           | NO      |
| events_waits_history_long      | NO      |
| global_instrumentation         | YES     |
| thread_instrumentation         | YES     |
| statements_digest              | YES     |
+--------------------------------+---------+
12 rows in set (0.00 sec)

mysql> UPDATE performance_schema.setup_consumers SET enabled= 'YES' WHERE name LIKE 'events\_stages\_%';
Query OK, 3 rows affected (0.08 sec)
Rows matched: 3  Changed: 3  Warnings: 0

mysql> UPDATE performance_schema.setup_consumers SET enabled= 'YES' WHERE name LIKE 'events\_statements\_%';
Query OK, 2 rows affected (0.00 sec)
Rows matched: 3  Changed: 2  Warnings: 0

mysql> SELECT * FROM performance_schema.setup_consumers;
+--------------------------------+---------+
| NAME                           | ENABLED |
+--------------------------------+---------+
| events_stages_current          | YES     |
| events_stages_history          | YES     |
| events_stages_history_long     | YES     |
| events_statements_current      | YES     |
| events_statements_history      | YES     |
| events_statements_history_long | YES     |
| events_waits_current           | NO      |
| events_waits_history           | NO      |
| events_waits_history_long      | NO      |
| global_instrumentation         | YES     |
| thread_instrumentation         | YES     |
| statements_digest              | YES     |
+--------------------------------+---------+
12 rows in set (0.00 sec)

次に、performance_schema.setup_instrumentsにあるstage/sql/*のENABLED = YESとTIMED = YESを設定します。

mysql> SELECT * FROM performance_schema.setup_instruments WHERE name LIKE 'stage/sql/%';
+---------------------------------------------------------------------------------------+---------+-------+
| NAME                                                                                  | ENABLED | TIMED |
+---------------------------------------------------------------------------------------+---------+-------+
| stage/sql/After create                                                                | NO      | NO    |
| stage/sql/allocating local table                                                      | NO      | NO    |
| stage/sql/preparing for alter table                                                   | NO      | NO    |
..
| stage/sql/Waiting for trigger metadata lock                                           | NO      | NO    |
| stage/sql/Waiting for event metadata lock                                             | NO      | NO    |
| stage/sql/Waiting for commit lock                                                     | NO      | NO    |
+---------------------------------------------------------------------------------------+---------+-------+
107 rows in set (0.00 sec)

mysql56> UPDATE performance_schema.setup_instruments SET ENABLED= 'YES', TIMED= 'YES' WHERE name LIKE 'stage/sql/%';
Query OK, 107 rows affected (0.00 sec)
Rows matched: 107  Changed: 107  Warnings: 0

mysql56> SELECT * FROM performance_schema.setup_instruments WHERE name LIKE 'stage/sql/%';
+---------------------------------------------------------------------------------------+---------+-------+
| NAME                                                                                  | ENABLED | TIMED |
+---------------------------------------------------------------------------------------+---------+-------+
| stage/sql/After create                                                                | YES     | YES   |
| stage/sql/allocating local table                                                      | YES     | YES   |
| stage/sql/preparing for alter table                                                   | YES     | YES   |
..
| stage/sql/Waiting for trigger metadata lock                                           | YES     | YES   |
| stage/sql/Waiting for event metadata lock                                             | YES     | YES   |
| stage/sql/Waiting for commit lock                                                     | YES     | YES   |
+---------------------------------------------------------------------------------------+---------+-------+
107 rows in set (0.00 sec)

これでSHOW PROFILEライクなperformance_schema.event_stages_*が有効になります（SHOW PROFILIEを利用した場合と比較するならばSET @@profiling = 1が終わったところ）。

ただし、@@profilingがセッション変数であるのに対し、performance_schemaはサーバー全体に影響を及ぼす（自セッション以外でもプロファイラーが有効になる）ので注意してください。自分以外のスレッドのプロファイリングを無効にする方法はいくつかありますが（performance_schema.setup_actorsやperformance_schema.threadsで調整する）、「どの項目を記録するか」の設定（performance_schema.setup_instruments,performance_schema.setup_consumers）の設定は全体で共有されるため、「自分以外のスレッドのプロファイリングを全て（今まで取得していた情報も全て）一時的に無効にする」または「自分以外のスレッドもSQL関連のプロファイリングも記録されることを諦めて短時間で元に戻す」のどちらかを選択することになります。

それでは、performance_schemaによるプロファイルの記録を見てみましょう。SHOW PROFILESおよびSHOW PROFILEの構文はシンプルでしたが、performance_schemaから同等の情報を得ようと思う場合はクエリーが長くなります。これには、以下のような理由が挙げられます（このあたりはMySQL 5.7以降でバンドルされるようになったsysスキーマ（次回で解説予定）が吸収してくれると嬉しいのだが）。

1. performance_schema上ではコネクションをthread_idで識別するが、通常のコネクションからはprocesslist_id（SHOW PFORCESLIST上のID） しか参照できないため、performance_schema.threadsをJOINして求めていること
2. performance_schema.events_stages_*上ではクエリーをnested_event_id単位で識別できるが、それをSQL_TEXTに紐付けるためにperformance_schema.events_statements_*をJOINして求めていること

mysql> SELECT
    ->   LEFT(performance_schema.events_statements_history.sql_text, 50) AS sql_text,
    ->   performance_schema.events_stages_history_long.event_name,
    ->   performance_schema.events_stages_history_long.timer_wait / (1000 * 1000 * 1000 * 1000) AS timer_wait_sec
    -> FROM
    ->   performance_schema.events_stages_history_long
    ->     JOIN
    ->       performance_schema.threads
    ->         USING(thread_id)
    ->     JOIN
    ->       performance_schema.events_statements_history
    ->         ON performance_schema.events_stages_history_long.nesting_event_id = performance_schema.events_statements_history.event_id
    -> WHERE
    ->   performance_schema.threads.processlist_id = @@pseudo_thread_id
    -> ORDER BY
    ->   performance_schema.events_stages_history_long.timer_start;
+----------------------------------+------------------------------------------+----------------+
| sql_text                         | event_name                               | timer_wait_sec |
+----------------------------------+------------------------------------------+----------------+
| select @@version_comment limit 1 | stage/sql/init                           |         0.0000 |
| select @@version_comment limit 1 | stage/sql/Waiting for query cache lock   |         0.0000 |
| select @@version_comment limit 1 | stage/sql/init                           |         0.0000 |
| select @@version_comment limit 1 | stage/sql/checking query cache for query |         0.0000 |
| select @@version_comment limit 1 | stage/sql/checking permissions           |         0.0000 |
| select @@version_comment limit 1 | stage/sql/Opening tables                 |         0.0000 |
| select @@version_comment limit 1 | stage/sql/init                           |         0.0000 |
| select @@version_comment limit 1 | stage/sql/optimizing                     |         0.0000 |
| select @@version_comment limit 1 | stage/sql/executing                      |         0.0000 |
| select @@version_comment limit 1 | stage/sql/end                            |         0.0000 |
| select @@version_comment limit 1 | stage/sql/query end                      |         0.0000 |
| select @@version_comment limit 1 | stage/sql/closing tables                 |         0.0000 |
| select @@version_comment limit 1 | stage/sql/freeing items                  |         0.0000 |
| select @@version_comment limit 1 | stage/sql/cleaning up                    |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/init                           |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/Waiting for query cache lock   |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/init                           |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/checking query cache for query |         0.0001 |
| SELECT * FROM d1.t1              | stage/sql/checking permissions           |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/Opening tables                 |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/init                           |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/System lock                    |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/optimizing                     |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/statistics                     |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/preparing                      |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/executing                      |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/Sending data                   |         0.0001 |
| SELECT * FROM d1.t1              | stage/sql/end                            |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/query end                      |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/closing tables                 |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/freeing items                  |         0.0000 |
| SELECT * FROM d1.t1              | stage/sql/cleaning up                    |         0.0000 |
+----------------------------------+------------------------------------------+----------------+
32 rows in set (0.00 sec)

長いクエリーですが、何とかSHOW PROFILEと似たような出力を得ることができました。筆者としてはSHOW PROFILEが廃止される前に、このあたりのインターフェースが整備されてくれることを望んでいます。筆者はストアドプロシージャでSHOW PROFILEに似た出力を出せるようにリクエストを出してみました（MySQL Bugs: #81928: Feature request for sys.profiling）が、ビューでも問題なく実装できると思います。

まとめ

SHOW PROFILEステートメントはMySQLサーバー組み込みのプロファイラーです。SET @@profiling = 1とすることでセッション単位で有効にできます（逆にグローバルに有効することも他のスレッドのプロファイルの内容を見ることもできない）。

プロファイラーが有効なケースは「EXPLAIN上問題ない（なさそうに見える）」「クエリーの遅さに再現性がある」場合ですが、クエリーのどこが遅いかわかっても、それを解消できるかどうかはまた別の問題です（インデックスを最大限活用しており、フェッチする行はこれ以上削れないにも関わらず"Sending data"で時間がかかっている場合など）。SHOW PROFILEステートメントはMySQL 5.6以降では「非推奨」のステータスとなっており、代替手段としてはperformance_schemaが案内されています。ただし、SHOW PROFILEとperformance_schemaの間には有効の仕方、情報の取得の仕方に大きな差異があります。