MySQL性能分析工具之PROFILE

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/