mysql profile_MySQL PROFILE 跟踪语句各阶段性能开销

PROFILE  可以跟踪查询语句各个阶段 Time，IO，CPU，MEMORY 等资源使用情况，比较详细。所以系统一般不会记录太多。启用是全局的，所以每个连接都保持语句的资源使用情况。

查看 PROFILE 是否启用：

MySQL> select @@profiling;

+-------------+

| @@profiling |

+-------------+

|           0 |

+-------------+

mysql> show variables like '%profiling%';

+------------------------+-------+

| variable_name          | value |

+------------------------+-------+

| have_profiling         | yes   |

| profiling              | off   |

| profiling_history_size | 15    |

+------------------------+-------+

mysql> select @@profiling;

+-------------+

| @@profiling |

+-------------+

| 0 |

+-------------+

mysql> show variables like '%profiling%';

+------------------------+-------+

| variable_name | value |

+------------------------+-------+

| have_profiling | yes |

| profiling | off |

| profiling_history_size | 15 |

+------------------------+-------+

have_profiling ：是否可使用 profiling

profiling ：是否启用

profiling_history_size ： 保留最近执行的记录数量。默认15，最大100，0相当于禁用。

启用(为全局变量)：

mysql> set profiling = 1;

mysql> set profiling_history_size = 10;

mysql> set profiling = 1;

mysql> set profiling_history_size = 10;

查看当前连接最近执行语句情况，编号越大为当前最近执行的。

mysql> show profiles;

+----------+------------+-----------------------------------------+

| query_id | duration   | query                                   |

+----------+------------+-----------------------------------------+

|        2 | 0.00705950 | show variables like '%profiling%'       |

|        3 | 0.00127400 | select * from mysql.user                |

|        4 | 0.00029100 | select * from mysql.user                |

|        5 | 0.00040850 | select * from mysql.user limit 10       |

|        6 | 5.00128000 | select sleep(5)                         |

|        7 | 0.00044425 | select * from mysql.user limit 1        |

|        8 | 0.00436100 | show variables like '%profiling%'       |

|        9 | 0.00047725 | select * from mysql.slow_log            |

|       10 | 0.00052150 | select * from mysql.slow_log order by 1 |

|       11 | 0.00049775 | select * from mysql.slow_log order by 2 |

+----------+------------+-----------------------------------------+

mysql> show profiles;

+----------+------------+-----------------------------------------+

| query_id | duration | query |

+----------+------------+-----------------------------------------+

| 2 | 0.00705950 | show variables like '%profiling%' |

| 3 | 0.00127400 | select * from mysql.user |

| 4 | 0.00029100 | select * from mysql.user |

| 5 | 0.00040850 | select * from mysql.user limit 10 |

| 6 | 5.00128000 | select sleep(5) |

| 7 | 0.00044425 | select * from mysql.user limit 1 |

| 8 | 0.00436100 | show variables like '%profiling%' |

| 9 | 0.00047725 | select * from mysql.slow_log |

| 10 | 0.00052150 | select * from mysql.slow_log order by 1 |

| 11 | 0.00049775 | select * from mysql.slow_log order by 2 |

+----------+------------+-----------------------------------------+

查看以上查询开销：SHOW PROFILE Syntax

SHOW PROFILE [type [, type] ... ]

[FOR QUERY n]

[LIMIT row_count [OFFSET offset]]

type:

ALL

| BLOCK IO

| CONTEXT SWITCHES

| CPU

| IPC

| MEMORY

| PAGE FAULTS

| SOURCE

| SWAPS

SHOW PROFILE [type [, type] ... ]

[FOR QUERY n]

[LIMIT row_count [OFFSET offset]]

type:

ALL

| BLOCK IO

| CONTEXT SWITCHES

| CPU

| IPC

| MEMORY

| PAGE FAULTS

| SOURCE

| SWAPS

默认显示时间信息，显示了该查询从开始到被清除各个阶段的执行时间。

mysql> show profile;

+----------------------+----------+

| Status               | Duration |

+----------------------+----------+

| starting             | 0.000090 |

| checking permissions | 0.000007 |

| Opening tables       | 0.000048 |

| init                 | 0.000033 |

| System lock          | 0.000006 |

| optimizing           | 0.000018 |

| statistics           | 0.000018 |

| preparing            | 0.000015 |

| Sorting result       | 0.000006 |

| executing            | 0.000328 |

| Sending data         | 0.000016 |

| Creating sort index  | 0.000081 |

| end                  | 0.000004 |

| query end            | 0.000006 |

| closing tables       | 0.000003 |

| removing tmp table   | 0.000005 |

| closing tables       | 0.000004 |

| freeing items        | 0.000068 |

| cleaning up          | 0.000017 |

+----------------------+----------+

mysql> show profile;

+----------------------+----------+

| Status | Duration |

+----------------------+----------+

| starting | 0.000090 |

| checking permissions | 0.000007 |

| Opening tables | 0.000048 |

| init | 0.000033 |

| System lock | 0.000006 |

| optimizing | 0.000018 |

| statistics | 0.000018 |

| preparing | 0.000015 |

| Sorting result | 0.000006 |

| executing | 0.000328 |

| Sending data | 0.000016 |

| Creating sort index | 0.000081 |

| end | 0.000004 |

| query end | 0.000006 |

| closing tables | 0.000003 |

| removing tmp table | 0.000005 |

| closing tables | 0.000004 |

| freeing items | 0.000068 |

| cleaning up | 0.000017 |

+----------------------+----------+

其他查看方法：

mysql> show profile;

mysql> select * from information_schema.profiling;

mysql> select * from information_schema.profiling where query_id=6 or

mysql> show profile;                 #默认显示时间信息

mysql> show profile CPU,BLOCK IO;        #(时间)加上 CPU,BLOCK IO 使用情况

mysql> show profile for query 6;     #query_id=6的(时间)信息

mysql> show profile CPU for query 6; #query_id=6的cpu信息

mysql> show profile CPU limit 6;     #前6个状态信息(前6行)

mysql> show profile CPU limit 6 offset 2;#第2行起前6个状态信息(前2~7行)

mysql> show profile;

mysql> select * from information_schema.profiling;

mysql> select * from information_schema.profiling where query_id=6 or

mysql> show profile;#默认显示时间信息

mysql> show profile CPU,BLOCK IO; #(时间)加上 CPU,BLOCK IO 使用情况

mysql> show profile for query 6;#query_id=6的(时间)信息

mysql> show profile CPU for query 6;#query_id=6的cpu信息

mysql> show profile CPU limit 6;#前6个状态信息(前6行)

mysql> show profile CPU limit 6 offset 2;#第2行起前6个状态信息(前2~7行)

关闭跟踪：

set profiling = 0;

set profiling_history_size = 0;

set profiling = 0;

set profiling_history_size = 0;

参考：