转载

MySQL性能分析工具之PROFILE

分析SQL执行带来的开销是优化SQL的常用手段，在MySQL数据库中，可以通过配置profiling参数来启用SQL剖析。
它只能在session级别来设置，设置后影响当前session；当它开启后，后续执行的SQL语句都将记录其资源开销，诸如IO，上下文，CPU，MEMORY等。

实验环境：

mysql> select version();
+------------+
| version() |
+------------+
| 5.7.17-log |
+------------+
1 row in set (0.00 sec)

与profile相关的三个参数：

mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES | ---用于控制是否由系统变量开启或禁用profiling
| profiling | OFF | ---开启SQL语句剖析功能
| profiling_history_size | 15 | ---设置保留profiling的数目，缺省为15，范围为0至100，为0时将禁用profiling
+------------------------+-------+
3 rows in set (0.01 sec)

开启profiling,有个警告，这个参数在以后会被删除，用information_scheam.PROFILING替代。

mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> show warnings;
+---------+------+----------------------------------------------------------------------+
| Level | Code | Message |
+---------+------+----------------------------------------------------------------------+
| Warning | 1287 | '@@profiling' is deprecated and will be removed in a future release. |
+---------+------+----------------------------------------------------------------------+

执行一条sql测试一下:

select * from oms3.customers where `type` = 1 AND `status` < 7 AND `isarea` = 6 AND `into_time`>='2016-12-01'AND `into_time`<='2017-01-02 23:59:59' order by score desc limit 40,20

sql执行很慢，执行完成之后查看:

mysql> show profiles;
+----------+--------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+--------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 7 | 0.00022275 | SELECT * FROM setup_actors |
| 8 | 0.00016050 | SELECT DATABASE() |
| 9 | 0.00032350 | show databases |
| 10 | 0.00024050 | show tables |
| 11 | 0.00019250 | SELECT * FROM setup_actors |
| 12 | 0.00183950 | show variables like "profiling_hist%" |
| 13 | 0.00192500 | show variables like '%profil%' |
| 14 | 0.00011550 | show warnings |
| 15 | 0.00044725 | help 'show profile' |
| 16 | 0.00013875 | set profiling=1 |
| 17 | 0.00011550 | show warnings |
| 18 | 0.00025075 | select * from customers where `type` = 1 AND `status` < 7 AND `isarea` = 6 AND `into_time`>='2016-12-01'AND `into_time`<='2017-01-02 23:59:59' order by score desc limit 40,20 |
| 19 | 333.19133875 | select * from oms3.customers where `type` = 1 AND `status` < 7 AND `isarea` = 6 AND `into_time`>='2016-12-01'AND `into_time`<='2017-01-02 23:59:59' order by score desc limit 40,20 |
| 20 | 0.00011250 | show profilings |
| 21 | 0.00010975 | show profilings |
+----------+--------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
15 rows in set, 1 warning (0.00 sec)
mysql> set @query_id=19; ---上面显示是query_id为19
Query OK, 0 rows affected (0.00 sec)
mysql> select STATE,sum(duration) as Total_R, ---用这条sql查询具体是哪里出问题，这条sql引用于《High Performance MySQL,Third Edition》
-> ROUND(
-> 100*SUM(DURATION)/
-> (SELECT SUM(DURATION) FROM INFORMATiON_SCHEMA.PROFILING WHERE QUERY_ID=@query_id),2) as Pct_R,
-> count(*) as calls,
-> sum(duration)/count(*) as "R/Call"
-> from information_schema.profiling
-> where query_id=@query_id
-> group by state
-> order by Total_R desc;
+----------------------+------------+-------+-------+----------------+
| STATE | Total_R | Pct_R | calls | R/Call |
+----------------------+------------+-------+-------+----------------+
| Sending data | 332.162424 | 99.69 | 1 | 332.1624240000 | ---这个state基本占用了全部的资源，那么对这条sql的优化就着重于减少io上。
| statistics | 1.027729 | 0.31 | 1 | 1.0277290000 |
| Opening tables | 0.000519 | 0.00 | 1 | 0.0005190000 |
| freeing items | 0.000157 | 0.00 | 1 | 0.0001570000 |
| starting | 0.000147 | 0.00 | 1 | 0.0001470000 |
| init | 0.000123 | 0.00 | 1 | 0.0001230000 |
| logging slow query | 0.000096 | 0.00 | 1 | 0.0000960000 |
| preparing | 0.000035 | 0.00 | 1 | 0.0000350000 |
| cleaning up | 0.000019 | 0.00 | 1 | 0.0000190000 |
| optimizing | 0.000016 | 0.00 | 1 | 0.0000160000 |
| end | 0.000014 | 0.00 | 1 | 0.0000140000 |
| System lock | 0.000014 | 0.00 | 1 | 0.0000140000 |
| closing tables | 0.000013 | 0.00 | 1 | 0.0000130000 |
| query end | 0.000013 | 0.00 | 1 | 0.0000130000 |
| Sorting result | 0.000010 | 0.00 | 1 | 0.0000100000 |
| checking permissions | 0.000009 | 0.00 | 1 | 0.0000090000 |
| executing | 0.000003 | 0.00 | 1 | 0.0000030000 |
+----------------------+------------+-------+-------+----------------+
17 rows in set, 18 warnings (0.00 sec)

其他用法：

mysql> SHOW PROFILE CPU FOR QUERY 2;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000038 | 0.000002 |
| creating table | 0.000056 | 0.000028 | 0.000028 |
| After create | 0.011363 | 0.000217 | 0.001571 |
| query end | 0.000375 | 0.000013 | 0.000028 |
| freeing items | 0.000089 | 0.000010 | 0.000014 |
| logging slow query | 0.000019 | 0.000009 | 0.000010 |
| cleaning up | 0.000005 | 0.000003 | 0.000002 |
+----------------------+----------+----------+------------+

更多用法详见：

help show profiles;

总结：

上面说到这个参数以后会被废弃，但是我觉得任重而道远，因为现在information_scheam.PROFILING表里连具体执行的sql都没记录......

PS:关于上面那条慢SQL的优化，请看我另一篇博客：http://blog.itpub.net/20893244/viewspace-2134636/

正文到此结束