MySQLのshow profileでクエリーの内部処理時間を調査

MySQLのshow profileで単一のクエリーの内部処理時間を調査する方法についてです。

スロークエリログの調査などで、実行時間が長いクエリーが特定できていて、そのクエリーの処理時間が長くなる原因を調査する際に有用です。
 

(1)プロファイルを有効にする


 
①設定を確認

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)

(2)show profileを実行


 
調査対象のクエリーを実行後、show profilesを実行します。
 
①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)

(3)プロファイル結果をカスタマイズして表示


 
実行結果をソートしたり、集計して表示する場合は、テーブルに直接アクセスします。プロファイルのデータはINFORMATION_SCHEMA.PROFILINGに保持されています。
 
1)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)

2)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)

3)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)
関連記事の目次

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です