http://blog.itpub.net/20893244/viewspace-2134879/
http://blog.itpub.net/29371470/viewspace-1355948/
MySQL性能分析工具之PROFILE 2017-03-07 21:19:17
分类： MySQL
分析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/