MySQLのshow profileで単一のクエリーの内部処理時間を調査する方法についてです。
スロークエリログの調査などで、実行時間が長いクエリーが特定できていて、そのクエリーの処理時間が長くなる原因を調査する際に有用です。
※目次をクリックすると目次の下部にコンテンツが表示されます。
プロファイルを有効にする
①設定を確認
mysql> show variables like 'profiling'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | profiling | OFF | +---------------+-------+ 1 row in set (0.01 sec)
②設定を有効にする
mysql> set profiling = 1; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> show variables like 'profiling'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | profiling | ON | +---------------+-------+ 1 row in set (0.00 sec)
show profileを実行
調査対象のクエリーを実行後、show profilesを実行します。
①show profilesで一覧表示し、調査対象のクエリIDを確認
①show profilesで一覧表示し、調査対象のクエリIDを確認
mysql> show profiles; +----------+------------+---------------------------------+ | Query_ID | Duration | Query | +----------+------------+---------------------------------+ | 1 | 0.00238325 | show variables like 'profiling' | | 2 | 0.00459550 | show variables like 'profiling' | | 3 | 0.00470500 | show variables like 'profiling' | | 4 | 0.00451175 | show variables like 'profiling' | | 5 | 7.80443025 | SELECT a,b,c・・・・・・・ | | 6 | 0.00458150 | show variables like 'profiling' | +----------+------------+---------------------------------+ 6 rows in set, 1 warning (0.00 sec)
②クエリIDを指定し、show profileを実行
mysql> show profile for query 5; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000063 | | Waiting for query cache lock | 0.000012 | | init | 0.000008 | | checking query cache for query | 0.000227 | | checking permissions | 0.000022 | | Opening tables | 0.071630 | | init | 0.000081 | | System lock | 0.000016 | | Waiting for query cache lock | 0.000005 | | System lock | 0.000043 | | optimizing | 0.000025 | | statistics | 0.000038 | | preparing | 0.000026 | | executing | 0.000004 | | Sending data | 7.241093 | | Waiting for query cache lock | 0.000025 | | Sending data | 0.145314 | | Waiting for query cache lock | 0.000016 | | Sending data | 0.345379 | | end | 0.000015 | | query end | 0.000013 | | closing tables | 0.000020 | | freeing items | 0.000019 | | Waiting for query cache lock | 0.000004 | | freeing items | 0.000283 | | Waiting for query cache lock | 0.000009 | | freeing items | 0.000004 | | storing result in query cache | 0.000006 | | cleaning up | 0.000034 | +--------------------------------+----------+ 29 rows in set, 1 warning (0.01 sec)
プロファイル結果をカスタマイズして表示
実行結果をソートしたり、集計して表示する場合は、テーブルに直接アクセスします。プロファイルのデータはINFORMATION_SCHEMA.PROFILINGに保持されています。
１）INFORMATION_SCHEMA.PROFILINGテーブルの定義内容
１）INFORMATION_SCHEMA.PROFILINGテーブルの定義内容
mysql> describe プロファイル結果をカスタマイズして表示; +---------------------+--------------+------+-----+----------+-------+ | Field | Type | Null | Key | Default | Extra | +---------------------+--------------+------+-----+----------+-------+ | QUERY_ID | int(20) | NO | | 0 | | | SEQ | int(20) | NO | | 0 | | | STATE | varchar(30) | NO | | | | | DURATION | decimal(9,6) | NO | | 0.000000 | | | CPU_USER | decimal(9,6) | YES | | NULL | | | CPU_SYSTEM | decimal(9,6) | YES | | NULL | | | CONTEXT_VOLUNTARY | int(20) | YES | | NULL | | | CONTEXT_INVOLUNTARY | int(20) | YES | | NULL | | | BLOCK_OPS_IN | int(20) | YES | | NULL | | | BLOCK_OPS_OUT | int(20) | YES | | NULL | | | MESSAGES_SENT | int(20) | YES | | NULL | | | MESSAGES_RECEIVED | int(20) | YES | | NULL | | | PAGE_FAULTS_MAJOR | int(20) | YES | | NULL | | | PAGE_FAULTS_MINOR | int(20) | YES | | NULL | | | SWAPS | int(20) | YES | | NULL | | | SOURCE_FUNCTION | varchar(30) | YES | | NULL | | | SOURCE_FILE | varchar(20) | YES | | NULL | | | SOURCE_LINE | int(20) | YES | | NULL | | +---------------------+--------------+------+-----+----------+-------+ 18 rows in set (0.13 sec)
２）DURATIONの降順に結果表示
mysql> SET @query_id = 5;
mysql> SELECT STATE, DURATION FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = @query_id ORDER BY DURATION DESC;
+--------------------------------+----------+
| STATE | DURATION |
+--------------------------------+----------+
| Sending data | 7.241093 |
| Sending data | 0.345379 |
| Sending data | 0.145314 |
| Opening tables | 0.071630 |
| freeing items | 0.000283 |
| checking query cache for query | 0.000227 |
| init | 0.000081 |
| starting | 0.000063 |
| System lock | 0.000043 |
| statistics | 0.000038 |
| cleaning up | 0.000034 |
| preparing | 0.000026 |
| optimizing | 0.000025 |
| Waiting for query cache lock | 0.000025 |
| checking permissions | 0.000022 |
| closing tables | 0.000020 |
| freeing items | 0.000019 |
| System lock | 0.000016 |
| Waiting for query cache lock | 0.000016 |
| end | 0.000015 |
| query end | 0.000013 |
| Waiting for query cache lock | 0.000012 |
| Waiting for query cache lock | 0.000009 |
| init | 0.000008 |
| storing result in query cache | 0.000006 |
| Waiting for query cache lock | 0.000005 |
| freeing items | 0.000004 |
| executing | 0.000004 |
| Waiting for query cache lock | 0.000004 |
+--------------------------------+----------+
29 rows in set (0.00 sec)
３）STATE毎にグループ化し、STATEの合計Durationの降順に表示
mysql> SELECT STATE, SUM(DURATION) AS Total FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = @query_id GROUP BY STATE ORDER BY Total DESC;
+--------------------------------+----------+
| STATE | Total |
+--------------------------------+----------+
| Sending data | 7.731786 |
| Opening tables | 0.071630 |
| freeing items | 0.000306 |
| checking query cache for query | 0.000227 |
| init | 0.000089 |
| Waiting for query cache lock | 0.000071 |
| starting | 0.000063 |
| System lock | 0.000059 |
| statistics | 0.000038 |
| cleaning up | 0.000034 |
| preparing | 0.000026 |
| optimizing | 0.000025 |
| checking permissions | 0.000022 |
| closing tables | 0.000020 |
| end | 0.000015 |
| query end | 0.000013 |
| storing result in query cache | 0.000006 |
| executing | 0.000004 |
+--------------------------------+----------+
18 rows in set (0.01 sec)