MySQL SQL Tuning：Profile定位單條QUERY效能瓶頸

不僅於事無補，還浪費了大量的人力和時間成本，甚至會拖垮伺服器
所以，我們在接受最佳化一條SQL，第一件事情便是要明白query病在哪裡？
是IO？是CPU?只有明白瓶頸在哪裡，方可對症下藥，也才能藥到病除
而MySQL QUERY Profiler是一個使用非常方便的QUERY診斷工具，5.0引入。5.1GA版嵌入
這個工具詳細呈現了SQL在整個生命週期的每個動作，這和Oracle開啟1046事件類別似
我們可以很清晰地明白該SQL是在資料存取還是運算(排序或分組等)上花費得多
那麼我們就不會很盲目地看到order by就去tuning sort buffer而忽略sorting result時間是如此之少

SHOW PROFILE [type [, type] ... ]    [FOR QUERY n]    [LIMIT row_count [OFFSET offset]]type:    ALL  | BLOCK IO  | CONTEXT SWITCHES  | CPU  | IPC  | MEMORY  | PAGE FAULTS  | SOURCE  | SWAPS

預設輸出結果只會展示Status和Duration，我們可以指定type來擴充輸出
我比較常用的是外加CPU和BLOCK IO來輸出CPU和IO的負載，其實這些已經夠了

預設profile是關閉的，通過profiling參數控制，為session級
開啟：SET profiling=1
關閉：set profiling=0
查詢：select @@profiling 
show profiles儲存的query條數由參數profiling_history_size控制，預設是15，超過了會把前面的剔掉

mysql> set profiling=1;mysql> select @@profiling;+-------------+| @@profiling |+-------------+|           1 |+-------------+mysql> select * from employees.t order by first_name;mysql> show profiles;+----------+------------+-----------------------------------------------+| Query_ID | Duration   | Query                                         |+----------+------------+-----------------------------------------------+|        1 | 0.21138800 | show create table employees.t                 ||        2 | 8.21691600 | select * from employees.t order by first_name |+----------+------------+-----------------------------------------------+2 rows in set (0.00 sec)mysql> show profile cpu,block io for query 2;+----------------------+----------+----------+------------+--------------+---------------+| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |+----------------------+----------+----------+------------+--------------+---------------+| starting             | 0.000160 | 0.000000 |   0.000000 |            0 |             0 || checking permissions | 0.000026 | 0.000000 |   0.000000 |            0 |             0 || Opening tables       | 0.000055 | 0.000000 |   0.000000 |            0 |             0 || System lock          | 0.000033 | 0.000000 |   0.000000 |            0 |             0 || init                 | 0.000050 | 0.000000 |   0.000000 |            0 |             0 || optimizing           | 0.000026 | 0.000000 |   0.000000 |            0 |             0 || statistics           | 0.000145 | 0.000000 |   0.000000 |            0 |             0 || preparing            | 0.000118 | 0.000000 |   0.000000 |            0 |             0 || executing            | 0.000011 | 0.000000 |   0.000000 |            0 |             0 || Sorting result       | 2.838465 | 1.396087 |   1.140071 |            0 |             0 || Sending data         | 0.928078 | 0.544034 |   0.056003 |            0 |             0 || end                  | 0.000026 | 0.000000 |   0.000000 |            0 |             0 || query end            | 0.000011 | 0.000000 |   0.000000 |            0 |             0 || closing tables       | 0.000021 | 0.000000 |   0.000000 |            0 |             0 || freeing items        | 4.449672 | 0.000000 |   0.000000 |            0 |             0 || logging slow query   | 0.000014 | 0.000000 |   0.000000 |            0 |             0 || cleaning up          | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |+----------------------+----------+----------+------------+--------------+---------------+17 rows in set (0.00 sec)

因為Profile預設是按執行順序排序的，而實際上我們更關心的是花費了多少時間，這才能方便知道哪些開銷較大

mysql> SELECT STATE, FORMAT(DURATION, 6) AS DURATION    -> FROM INFORMATION_SCHEMA.PROFILING    -> WHERE QUERY_ID = 2 ORDER BY DURATION DESC;+----------------------+----------+| STATE                | DURATION |+----------------------+----------+| freeing items        | 4.449672 || Sorting result       | 2.838465 || Sending data         | 0.928078 || starting             | 0.000160 || statistics           | 0.000145 || preparing            | 0.000118 || Opening tables       | 0.000055 || init                 | 0.000050 || System lock          | 0.000033 || end                  | 0.000026 || optimizing           | 0.000026 || checking permissions | 0.000026 || closing tables       | 0.000021 || logging slow query   | 0.000014 || query end            | 0.000011 || executing            | 0.000011 || cleaning up          | 0.000005 |+----------------------+----------+17 rows in set (0.00 sec)

http://dev.mysql.com/doc/refman/5.5/en/show-profile.html


By 迦夜
2013-10-3
Good Luck