如何使用mysql profiling功能分析单条查询语句

小程序：扫一扫查出行
【扫一扫了解最新限行尾号】
复制小程序

Mysql从5.1版本开始引入show profile来剖析单条语句功能

一、查看是否支持这个功能

yes表示支持

二、使用步骤

1.在 sql命令行中输入：set profiling=1;来开启（当前会话关闭前，只需要执行一次）

mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

2.然后在服务器上执行你的SQL语句，都会被测量其消耗的时间和其他一些查询执行状态变更相关的数据

mysql> select count(*) from he_store_discount;
+----------+
| count(*) |
+----------+
| 1 |
+----------+
1 row in set (0.00 sec)

3. 然后再执行：show prifiles;命令，所有的查询SQL都会被列出来

mysql> show profiles;
+----------+------------+----------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+----------------------------------------+
| 1 | 0.00013000 | select count(*) from he_store_discount |
| 2 | 0.00290900 | show databases |
| 3 | 0.00016200 | SELECT DATABASE() |
| 4 | 0.00052800 | show databases |
| 5 | 0.00204500 | show tables |
| 6 | 0.00027000 | select count(*) from he_store_discount |
+----------+------------+----------------------------------------+
6 rows in set, 1 warning (0.00 sec)

4.然后再根据编号(即Query_ID)查询具体SQL的执行过程

mysql> show profile for query 1;
+---------------+----------+
| Status | Duration |
+---------------+----------+
| starting | 0.000091 |
| freeing items | 0.000028 |
| cleaning up | 0.000011 |
+---------------+----------+
3 rows in set, 1 warning (0.01 sec)mysql> show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000044 |
| checking permissions | 0.000011 |
| Opening tables | 0.000039 |
| init | 0.000013 |
| System lock | 0.000008 |
| optimizing | 0.000006 |
| statistics | 0.000012 |
| preparing | 0.000012 |
| executing | 0.002696 |
| Sending data | 0.000021 |
| end | 0.000004 |
| query end | 0.000006 |
| closing tables | 0.000003 |
| removing tmp table | 0.000006 |
| closing tables | 0.000003 |
| freeing items | 0.000017 |
| cleaning up | 0.000008 |
+----------------------+----------+
17 rows in set, 1 warning (0.00 sec)mysql> show profile for query 3;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000046 |
| checking permissions | 0.000009 |
| Opening tables | 0.000008 |
| init | 0.000014 |
| optimizing | 0.000008 |
| executing | 0.000012 |
| end | 0.000006 |
| query end | 0.000008 |
| closing tables | 0.000007 |
| freeing items | 0.000027 |
| cleaning up | 0.000017 |
+----------------------+----------+
11 rows in set, 1 warning (0.00 sec)

5.当查到最耗时的线程状态时，可以进一步选择all或者cpu,block io,page faults等明细类型来查看mysql在每个线程状态中使用什么资源上耗费了过高的时间：

mysql> show profile all for query 1;
+---------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+---------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
| starting | 0.000091 | 0.000073 | 0.000012 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| freeing items | 0.000028 | 0.000016 | 0.000011 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 5593 |
| cleaning up | 0.000011 | 0.000008 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1902 |
+---------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+--------------+-------------+
3 rows in set, 1 warning (0.00 sec)mysql> show profile cpu for query 1;
+---------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+---------------+----------+----------+------------+
| starting | 0.000091 | 0.000073 | 0.000012 |
| freeing items | 0.000028 | 0.000016 | 0.000011 |
| cleaning up | 0.000011 | 0.000008 | 0.000003 |
+---------------+----------+----------+------------+
3 rows in set, 1 warning (0.00 sec)mysql> show profile block io for query 1;
+---------------+----------+--------------+---------------+
| Status | Duration | Block_ops_in | Block_ops_out |
+---------------+----------+--------------+---------------+
| starting | 0.000091 | 0 | 0 |
| freeing items | 0.000028 | 0 | 0 |
| cleaning up | 0.000011 | 0 | 0 |
+---------------+----------+--------------+---------------+
3 rows in set, 1 warning (0.00 sec)mysql> show profile page faults for query 1;
+---------------+----------+-------------------+-------------------+
| Status | Duration | Page_faults_major | Page_faults_minor |
+---------------+----------+-------------------+-------------------+
| starting | 0.000091 | 0 | 0 |
| freeing items | 0.000028 | 0 | 0 |
| cleaning up | 0.000011 | 0 | 0 |
+---------------+----------+-------------------+-------------------+
3 rows in set, 1 warning (0.00 sec)