第130回　クエリをプロファイリングしてみる

MySQLを運用していくうえで、スロークエリを見つけてしまった場合等に、そのクエリはどういった処理が遅いのだろうかと疑問に思ったことはあるのではないでしょうか。

MySQLには、クエリプロファイリング機能としてSHOW PROFILE構文があります。これは、実行したクエリの各処理にどれくらいの時間がかかったのかを計測して表示することができます。2020年9月現在、このSHOW PROFILE構文は非推奨ではありますが、利用することができます。また、このツールの代替として、公式ドキュメントにはPerformance Schemaを利用するようにと書かれています。

今回は、SHOW PROFILE構文やPerformance Schemaを利用して処理の実行時間の計測を行ってみます。なお、利用している環境はCentOS 7、MySQLのバージョンは8.0.21を利用しています。

SHOW PROFILE構文

SHOW PROFILE構文は、冒頭でも説明したように非推奨ではあるものの、利用は可能です。利用するためには、まず SET profiling = 1でプロファイルを有効にする必要があります。有効かどうか確認するにはSELECT @@profiling、またはSHOW VARIABLESで確認することができます。

mysql> SHOW VARIABLES like 'profil';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| profiling              | ON    |
| profiling_history_size | 15    |
+------------------------+-------+
2 rows in set (0.00 sec)

profiling_history_sizeは、最大いくつのクエリをセッション単位で保持するのか設定でき、デフォルト15、最大100まで設定できます。profilingを有効にして、計測したいクエリを実行後、SHOW PROFILESを実行するとQuery_IDと計測したときの時間が表示されます。

mysql> show profiles;
+----------+------------+----------------------------------+
| Query_ID | Duration   | Query                            |
+----------+------------+----------------------------------+
|        1 | 0.00019425 | select @@version_comment limit 1 |
|        2 | 0.00015375 | SELECT DATABASE()                |
|        3 | 0.00015900 | SET profiling = 1                |
|        4 | 0.00005975 | show warnings                    |
|        5 | 0.00537800 | SELECT count(1) FROM t1          |
+----------+------------+----------------------------------+
5 rows in set, 1 warning (0.00 sec)

SHOW PROFILE FOR QUERY <Query_ID>を実行すると、指定したQuery_IDに関するプロファイル情報をクエリの実行ステップごとに確認することができます。もしFOR QUERYを使わずに実行した場合は、直近に実行されたクエリが選択されます。

mysql> SHOW PROFILE;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000163 |
| Executing hook on transaction  | 0.000011 |
| starting                       | 0.000023 |
| checking permissions           | 0.000011 |
| Opening tables                 | 0.000169 |
| init                           | 0.000010 |
| System lock                    | 0.000016 |
| optimizing                     | 0.000005 |
| optimizing                     | 0.000004 |
| statistics                     | 0.000059 |
| preparing                      | 0.000044 |
| Creating tmp table             | 0.000051 |
（以下省略）

デフォルトではStatusとDurationが表示されますが、オプションを利用することで表示する項目を変更することができます。

option	説明
ALL	全情報を表示
BLOCK IO	BLOCK I/Oの回数
CONTEXT SWITCHES	コンテキストスイッチの回数
CPU	CPU時間
IPC	メッセージの送受信
PAGE FAULTS	ページフォルト回数
SOURCE	ソースコードのファイル名と関数名、及び行番号の表示
SWAPS	スワップの回数

mysql> SHOW PROFILE SOURCE;
+--------------------------------+----------+---------------------------+----------------------+-------------+
| Status                         | Duration | Source_function           | Source_file          | Source_line |
+--------------------------------+----------+---------------------------+----------------------+-------------+
| starting                       | 0.000092 | NULL                      | NULL                 |        NULL |
| Executing hook on transaction  | 0.000008 | launch_hook_trans_begin   | rpl_handler.cc       |        1122 |
| starting                       | 0.000015 | launch_hook_trans_begin   | rpl_handler.cc       |        1124 |
| checking permissions           | 0.000008 | check_access              | sql_authorization.cc |        2207 |
| Opening tables                 | 0.000083 | open_tables               | sql_base.cc          |        5605 |
| init                           | 0.000009 | execute                   | sql_select.cc        |         684 |
| System lock                    | 0.000011 | mysql_lock_tables         | lock.cc              |         329 |
| optimizing                     | 0.000008 | optimize                  | sql_optimizer.cc     |         282 |
| optimizing                     | 0.000007 | optimize                  | sql_optimizer.cc     |         282 |
| statistics                     | 0.000024 | optimize                  | sql_optimizer.cc     |         504 |
| preparing                      | 0.000017 | optimize                  | sql_optimizer.cc     |         588 |
| Creating tmp table             | 0.000054 | create_intermediate_table | sql_executor.cc      |         198 |
（以下省略）

同様の情報はInformation Schemaのprofilingテーブルからも取得することが可能です。通常SHOW PROFILE構文ではorder byを使った並び替えはできませんが、秒数順に並び替えたい場合等は、Information Schemaのprofilingテーブルを参照すると良いかと思います。

ここでSHOW PROFILEを利用する際にはいくつか注意が必要です。公式ドキュメントにもある通り、CPU情報はgetrusage（RUSAGE_SELF, &rusage）から取得しているため、スレッド単位ではなくプロセス単位となります。そのため、実行タイミングによっては値が大きく変わってしまうことがあるかもしれません。また、実際にSHOW PROFILE構文を利用すると、下記のようにPerformance Schemaを利用するようにとワーニングが表示されます。Performance Schemaを利用するやり方については、次の項目を参考にしてください。

Warning (Code 1287): 'SHOW PROFILE' is deprecated and will be removed in a future release. Please use Performance Schema instead

Performance Schemaを利用した計測

続いて、Performance Schemaを利用した方法を紹介します。公式ドキュメントにもある通り現在はこちらの利用が推奨されています。

ただし、Performance Schemaを利用する場合は他のスレッドで実行されているクエリも計測対象となってしまうため、通常より高負荷となる可能性があります。利用の際は開発環境に留めるか、すぐにOFFにできるように準備をしておくことをおすすめします。

Performance Schemaを利用して計測するには、setup_instrumentsとsetup_consumersの計測したい各項目の値を変更することで計測できます。setup_instrumentsの場合はNAMEが'%statement/%'と'%stage/%'に該当するENABLEDとTIMEDカラムの値を'YES'に変更し、setup_consumersで'%events_statements_%'と'%events_stages_%'に該当するNAMEをENABLED = 'YES'とすることでプロファイリングを開始します。下記の例では該当するすべての項目を計測対象とするクエリです。

mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME LIKE '%statement/%';
mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME LIKE '%stage/%';

mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE '%events_statements_%';
mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE '%events_stages_%';

このクエリを実行すると、Performance Schemaのevents_statements_history_longテーブルにevent_idとsql_textが保存されるようになるので、対象のクエリを実行後、計測したいクエリのevent_idを抽出します。

event_idを抽出後は、events_stages_history_longテーブルのnesting_event_idを先程のevent_idで絞ることでプロファイリング情報を確認することができます。

公式ドキュメントにも説明がある通り、TIMER_WAITの値はピコ秒（1兆分の1秒）なので、1000000000000で値を割ることで、秒数として確認することができます。

mysql> SELECT event_name, source, truncate(timer_wait/1000000000000, 6) as duration  FROM performance_schema.events_stages_history_long where NESTING_EVENT_ID = 74;
+------------------------------------------------+----------------------------------+----------+
| event_name                                     | source                           | duration |
+------------------------------------------------+----------------------------------+----------+
| stage/sql/starting                             | init_net_server_extension.cc:101 | 0.000257 |
| stage/sql/Executing hook on transaction begin. | rpl_handler.cc:1122              | 0.000011 |
| stage/sql/starting                             | rpl_handler.cc:1124              | 0.000030 |
| stage/sql/checking permissions                 | sql_authorization.cc:2207        | 0.000011 |
| stage/sql/Opening tables                       | sql_base.cc:5605                 | 0.000246 |
| stage/sql/init                                 | sql_select.cc:684                | 0.000025 |
| stage/sql/System lock                          | lock.cc:329                      | 0.000026 |
| stage/sql/optimizing                           | sql_optimizer.cc:282             | 0.000009 |
| stage/sql/optimizing                           | sql_optimizer.cc:282             | 0.000004 |
| stage/sql/statistics                           | sql_optimizer.cc:504             | 0.000061 |
| stage/sql/preparing                            | sql_optimizer.cc:588             | 0.000022 |
| stage/sql/Creating tmp table                   | sql_executor.cc:198              | 0.000061 |
（以下省略）

まとめ

今回は、SHOW PROFILE構文とPerformance Schemaを利用してクエリをプロファイルするやり方を紹介しました。実際に利用することで、どういった処理に時間がかかっているかを特定でき、何が問題なのかを導きだすことができるかもしれません。問題解決のアプローチのひとつとして利用していただければと思います。