MySQL profiling剖析SQL

轉自  https://www.cnblogs.com/xiaoboluo768/p/5157909.html

5.1版本開始引入show profile剖析單條語句功能，支援show profiles和show profile語句，引數have_profiling;控制是否開啟：

檢視是否支援這個功能（查詢為yes表示支援）：

mysql > show variables like 'have_profiling';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| have_profiling | YES   |
+----------------+-------+
1 row in set (0.00 sec)

 

 需要臨時使用時直接sql命令列中輸入：set profiling=1;來開啟

mysql> set profiling=1;

Query OK, 0 rows affected, 1 warning (0.00 sec)

 

然後在伺服器上執行SQL語句，都會被測量其消耗的時間和其他一些查詢執行狀態變更相關的資料

mysql> select count(*) from xx;

+----------+

| count(*) |

+----------+

|   262144 |

+----------+

1 row in set (0.05 sec)

 

然後再執行：show prifiles;命令，所有的查詢SQL都會被列出來

mysql> show profiles;

+----------+------------+-------------------------+

| Query_ID | Duration   | Query                   |

+----------+------------+-------------------------+

|        1 | 0.05645950 | select count(*) from xx |

+----------+------------+-------------------------+

1 row in set, 1 warning (0.00 sec)

 

然後根據編號查詢具體SQL的執行過程，這裡演示只執行了一句，那就選項query id為1

mysql> show profile for query 1;

+----------------------+----------+

| Status               | Duration |

+----------------------+----------+

| starting             | 0.000041 |

| checking permissions | 0.000004 |

| Opening tables       | 0.000017 |

| init                 | 0.000010 |

| System lock          | 0.000006 |

| optimizing           | 0.000004 |

| statistics           | 0.000009 |

| preparing            | 0.000008 |

| executing            | 0.000001 |

| Sending data         | 0.056110 |

| end                  | 0.000009 |

| query end            | 0.000007 |

| closing tables       | 0.000011 |

| freeing items        | 0.000121 |

| logging slow query   | 0.000001 |

| logging slow query   | 0.000093 |

| cleaning up          | 0.000010 |

+----------------------+----------+

17 rows in set, 1 warning (0.00 sec)

 

當查到最耗時的執行緒狀態時，可以進一步選擇all或者cpu,block io,page faults等明細型別來檢視mysql在每個執行緒狀態中使用什麼資源上耗費了過高的時間：

show profile cpu for query 2;

  

上面的輸出中可以以很高的精度顯示了查詢的響應時間，列出了查詢執行的每個步驟花費的時間，其結果很難確定哪個步驟花費的時間太多，因為輸出是按照執行順序排序，而不是按照花費大小來排序的，如果要按照花費大小排序，就不能使用show prifile命令，而是直接使用information_schema.profiling表。如：

mysql> set profiling=1;

Query OK, 0 rows affected, 1 warning (0.00 sec)

 

mysql> select count(*) from xx;

+----------+

| count(*) |

+----------+

|   262144 |

+----------+

1 row in set (0.05 sec)

 

mysql> show profiles;

+----------+------------+-------------------------+

| Query_ID | Duration   | Query                   |

+----------+------------+-------------------------+

|        1 | 0.05509950 | select count(*) from xx |

+----------+------------+-------------------------+

1 row in set, 1 warning (0.00 sec)

 

mysql> set @query_id=1;

Query OK, 0 rows affected (0.00 sec)

 

mysql> select state,sum(duration) as total_r,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         | 0.054629 | 99.14 |     1 | 0.0546290000 |

| freeing items        | 0.000267 |  0.48 |     1 | 0.0002670000 |

| logging slow query   | 0.000070 |  0.13 |     2 | 0.0000350000 |

| starting             | 0.000040 |  0.07 |     1 | 0.0000400000 |

| Opening tables       | 0.000016 |  0.03 |     1 | 0.0000160000 |

| closing tables       | 0.000011 |  0.02 |     1 | 0.0000110000 |

| init                 | 0.000010 |  0.02 |     1 | 0.0000100000 |

| cleaning up          | 0.000010 |  0.02 |     1 | 0.0000100000 |

| end                  | 0.000009 |  0.02 |     1 | 0.0000090000 |

| statistics           | 0.000009 |  0.02 |     1 | 0.0000090000 |

| preparing            | 0.000008 |  0.01 |     1 | 0.0000080000 |

| query end            | 0.000007 |  0.01 |     1 | 0.0000070000 |

| System lock          | 0.000006 |  0.01 |     1 | 0.0000060000 |

| checking permissions | 0.000005 |  0.01 |     1 | 0.0000050000 |

| optimizing           | 0.000004 |  0.01 |     1 | 0.0000040000 |

| executing            | 0.000001 |  0.00 |     1 | 0.0000010000 |

+----------------------+----------+-------+-------+--------------+

16 rows in set (0.01 sec)

 

從上面的結果中可以看到，第一個是sending data（如果產生了臨時表，第一就不是它了，那麼臨時表也是優先要解決的最佳化問題），另外還有sorting result（結果排序）也要注意，如果佔比比較高，也要想辦法最佳化，一般不建議在tuning sort buffer（最佳化排序緩衝區）或者類似的活動上花時間去最佳化。

 

如果要查詢query id為1的Sending data狀態的詳細資訊，可以使用如下SQL查詢：

select * from information_schema.profiling where query_id=1 and state='Sending data'\G;

 

最後，做完剖析測試別忘記 斷開你的連線或者 set profiling=0 關閉這個功能。