MySQL中使用PROFILING来查看SQL执行流程

jiawang

在MySQL中，PROFILING功能提供了一种方式来分析sql语句执行时间，包括查询执行的各个阶段，如发送、解析、优化、执行等。
使用PROFILING来查看SQL执行流程。以下是如何开启和使用PROFILING的步骤


1、开启Profiling

1.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)

执行要分析的SQL查询。

mysql> show tables
    -> ;
+----------------+
| Tables_in_test |
+----------------+
| my_table       |
| tmp            |
| tmp_table      |
+----------------+
3 rows in set (0.00 sec)


mysql> select * from my_table;
+----+-------+-----+
| id | name  | age |
+----+-------+-----+
|  1 | Tom   |  25 |
|  2 | Tom   |  25 |
|  3 | Jerry |  30 |
|  4 | Alice |  28 |
+----+-------+-----+
4 rows in set (0.00 sec)


执行查询后，你可以通过以下命令查看所有查询的Profile
mysql>  show profiles;
+----------+------------+---------------------------------+
| Query_ID | Duration   | Query                           |
+----------+------------+---------------------------------+
|        1 | 0.00116575 | show variables like 'profiling' |
|        2 | 0.00084675 | show tables                     |
|        3 | 0.00038900 | select * from my_table          |
+----------+------------+---------------------------------+
3 rows in set, 1 warning (0.00 sec)
这将列出所有已执行的查询及其查询编号（Query_ID）。
mysql>


选择你想要查看详细Profile的查询编号，然后使用以下命令：
mysql> select * from tmp_table;
Empty set (0.00 sec)


mysql>  show profiles;
+----------+------------+---------------------------------+
| Query_ID | Duration   | Query                           |
+----------+------------+---------------------------------+
|        1 | 0.00116575 | show variables like 'profiling' |
|        2 | 0.00084675 | show tables                     |
|        3 | 0.00038900 | select * from my_table          |
|        4 | 0.00034225 | select * from tmp_table         |
+----------+------------+---------------------------------+
4 rows in set, 1 warning (0.00 sec)


mysql> show profile for query 4;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000074 |
| Executing hook on transaction  | 0.000004 |
| starting                       | 0.000007 |
| checking permissions           | 0.000005 |
| Opening tables                 | 0.000029 |
| init                           | 0.000005 |
| System lock                    | 0.000007 |
| optimizing                     | 0.000003 |
| statistics                     | 0.000012 |
| preparing                      | 0.000014 |
| executing                      | 0.000061 |
| end                            | 0.000005 |
| query end                      | 0.000002 |
| waiting for handler commit     | 0.000007 |
| closing tables                 | 0.000008 |
| freeing items                  | 0.000014 |
| cleaning up                    | 0.000087 |
+--------------------------------+----------+
17 rows in set, 1 warning (0.00 sec)


或者，你可以查看该查询的特定方面，如CPU_TIME、CONTEXT_SWITCHES等：
mysql> SHOW PROFILE CPU, BLOCK IO FOR QUERY 4;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000074 | 0.000073 |   0.000000 |            0 |             0 |
| Executing hook on transaction  | 0.000004 | 0.000003 |   0.000000 |            0 |             0 |
| starting                       | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| checking permissions           | 0.000005 | 0.000005 |   0.000000 |            0 |             0 |
| Opening tables                 | 0.000029 | 0.000029 |   0.000000 |            0 |             0 |
| init                           | 0.000005 | 0.000005 |   0.000000 |            0 |             0 |
| System lock                    | 0.000007 | 0.000006 |   0.000000 |            0 |             0 |
| optimizing                     | 0.000003 | 0.000003 |   0.000000 |            0 |             0 |
| statistics                     | 0.000012 | 0.000012 |   0.000000 |            0 |             0 |
| preparing                      | 0.000014 | 0.000014 |   0.000000 |            0 |             0 |
| executing                      | 0.000061 | 0.000062 |   0.000000 |            0 |             0 |
| end                            | 0.000005 | 0.000004 |   0.000000 |            0 |             0 |
| query end                      | 0.000002 | 0.000003 |   0.000000 |            0 |             0 |
| waiting for handler commit     | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| closing tables                 | 0.000008 | 0.000008 |   0.000000 |            0 |             0 |
| freeing items                  | 0.000014 | 0.000014 |   0.000000 |            0 |             0 |
| cleaning up                    | 0.000087 | 0.000088 |   0.000000 |            0 |             0 |
+--------------------------------+----------+----------+------------+--------------+---------------+
17 rows in set, 1 warning (0.00 sec)




查看 profiling 系统变量


root@localhost [wjq]>show variables like '%profil%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.00 sec)


参数说明：


have_profiling:只读变量，用于控制是否有系统变量开启或关闭 profiling


profiling：开启或关系 SQ L语句剖析功能


profiling_history_size：设置保留 profiling 的数据，默认是 15，范围为 0~100，0 表示将禁用 profiling


获取 profiling 的帮助信息


root@localhost [wjq]>help profile
Name: 'SHOW PROFILE'
Description:
Syntax:
SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL                 #显示所有的开销信息
  | BLOCK IO            #显示块IO的开销信息
  | CONTEXT SWITCHES    #上下文切换开销信息
  | CPU                 #显示CPU相关开销信息
  | IPC                 #显示发送和接受相关开销信息
  | MEMORY              #显示内存相关开销信息
  | PAGE FAULTS         #显示页面错误相关开销信息
  | SOURCE              #显示和source_funcation、source_file、source_line相关的开销信息
  | SWAPS               #显示交换次数相关开销信息

The SHOW PROFILE and SHOW PROFILES statements display profiling
information that indicates resource usage for statements executed
during the course of the current session.