MySQL道普請便り
第130回 クエリをプロファイリングしてみる
MySQLを運用していくうえで，
MySQLには，
今回は，
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_は，SHOW PROFILESを実行するとQuery_
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_を実行すると，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/ |
| 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を使った並び替えはできませんが，profilingテーブルを参照すると良いかと思います。
ここでSHOW PROFILEを利用する際にはいくつか注意が必要です。公式ドキュメントにもある通り，
Warning (Code 1287): 'SHOW PROFILE' is deprecated and will be removed in a future release. Please use Performance Schema instead
Performance Schemaを利用した計測
続いて，
ただし，
Performance Schemaを利用して計測するには，
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_%';
このクエリを実行すると，events_テーブルにevent_
event_events_テーブルのnesting_
公式ドキュメントにも説明がある通り，
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 | （以下省略）
まとめ
今回は，