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

共计 5343 个字符，预计需要花费 14 分钟才能阅读完成。

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

查看 PROFILE 是否启用：

1. MySQL> select @@profiling; 
2. +————-+ 
3. | @@profiling | 
4. +————-+ 
5. |           0 | 
6. +————-+ 
7.  
8. mysql> show variables like ‘%profiling%’; 
9. +————————+——-+ 
10. | variable_name          | value | 
11. +————————+——-+ 
12. | have_profiling         | yes   | 
13. | profiling              | off   | 
14. | profiling_history_size | 15    | 
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;

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

1. mysql> show profiles; 
2. +———-+————+—————————————–+ 
3. | query_id | duration   | query                                   | 
4. +———-+————+—————————————–+ 
5. |        2 | 0.00705950 | show variables like ‘%profiling%’       | 
6. |        3 | 0.00127400 | select * from mysql.user                | 
7. |        4 | 0.00029100 | select * from mysql.user                | 
8. |        5 | 0.00040850 | select * from mysql.user limit 10       | 
9. |        6 | 5.00128000 | select sleep(5)                         | 
10. |        7 | 0.00044425 | select * from mysql.user limit 1        | 
11. |        8 | 0.00436100 | show variables like ‘%profiling%’       | 
12. |        9 | 0.00047725 | select * from mysql.slow_log            | 
13. |       10 | 0.00052150 | select * from mysql.slow_log order by 1 | 
14. |       11 | 0.00049775 | select * from mysql.slow_log order by 2 | 
15. +———-+————+—————————————–+ 

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

1. SHOW PROFILE [type [, type] … ] 
2.     [FOR QUERY n] 
3.     [LIMIT row_count [OFFSET offset]] 
4.  
5. type: 
6.     ALL 
7.   | BLOCK IO 
8.   | CONTEXT SWITCHES 
9.   | CPU 
10.   | IPC 
11.   | MEMORY 
12.   | PAGE FAULTS 
13.   | SOURCE 
14.   | 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

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

1. mysql> show profile; 
2. +———————-+———-+ 
3. | Status               | Duration | 
4. +———————-+———-+ 
5. | starting             | 0.000090 | 
6. | checking permissions | 0.000007 | 
7. | Opening tables       | 0.000048 | 
8. | init                 | 0.000033 | 
9. | System lock          | 0.000006 | 
10. | optimizing           | 0.000018 | 
11. | statistics           | 0.000018 | 
12. | preparing            | 0.000015 | 
13. | Sorting result       | 0.000006 | 
14. | executing            | 0.000328 | 
15. | Sending data         | 0.000016 | 
16. | Creating sort index  | 0.000081 | 
17. | end                  | 0.000004 | 
18. | query end            | 0.000006 | 
19. | closing tables       | 0.000003 | 
20. | removing tmp table   | 0.000005 | 
21. | closing tables       | 0.000004 | 
22. | freeing items        | 0.000068 | 
23. | cleaning up          | 0.000017 | 
24. +———————-+———-+ 

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 |
+----------------------+----------+

其他查看方法：

1. mysql> show profile; 
2. mysql> select * from information_schema.profiling; 
3. mysql> select * from information_schema.profiling where query_id=6 or 
4.  
5. mysql> show profile;                 #默认显示时间信息 
6. mysql> show profile CPU,BLOCK IO;        #(时间)加上 CPU,BLOCK IO 使用情况 
7. mysql> show profile for query 6;     #query_id= 6 的 (时间) 信息 
8. mysql> show profile CPU for query 6; #query_id= 6 的 cpu 信息 
9. mysql> show profile CPU limit 6;     #前 6 个状态信息(前 6 行) 
10. 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;

参考： 

SHOW PROFILE Syntax

The INFORMATION_SCHEMA PROFILING Table

本文永久更新链接地址：http://www.linuxidc.com/Linux/2017-05/143920.htm