MySQL中使用SHOW PROFILE命令分析效能的用法整理_Mysql

show profile是由Jeremy Cole捐獻給MySQL社區版本的。預設的是關閉的，但是會話層級可以開啟這個功能。開啟它可以讓MySQL收集在執行語句的時候所使用的資源。為了統計報表,把profiling設為1
 

mysql> SET profiling = 1;

 
之後在運行一個查詢

mysql> SELECT COUNT(DISTINCT actor.first_name) AS cnt_name, COUNT(*) AS cnt-> FROM sakila.film_actor-> INNER JOIN sakila.actor USING(actor_id)-> GROUP BY sakila.film_actor.film_id-> ORDER BY cnt_name DESC;...997 rows in set (0.03 sec)

 
這個執行語句的剖析資訊儲存在這個會話中。使用SHOW PROFILES進行查看。

mysql> SHOW PROFILES\G

*************************** 1. row ***************************Query_ID: 1Duration: 0.02596900Query: SELECT COUNT(DISTINCT actor.first_name) AS cnt_name,...

 
你可以使用SHOW PROFILE語句來擷取已經儲存的剖析資料。如果不加參數，會顯示狀態以及它們持續的時間。

mysql> SHOW PROFILE;

+------------------------+-----------+| Status | Duration |+------------------------+-----------+| (initialization) | 0.000005 || Opening tables | 0.000033 || System lock | 0.000037 || Table lock | 0.000024 || init | 0.000079 || optimizing | 0.000024 || statistics | 0.000079 || preparing | 0.00003 || Creating tmp table | 0.000124 || executing | 0.000008 || Copying to tmp table | 0.010048 || Creating sort index | 0.004769 || Copying to group table | 0.0084880 || Sorting result | 0.001136 || Sending data | 0.000925 || end | 0.00001 || removing tmp table | 0.00004 || end | 0.000005 || removing tmp table | 0.00001 || end | 0.000011 || query end | 0.00001 || freeing items | 0.000025 || removing tmp table | 0.00001 || freeing items | 0.000016 || closing tables | 0.000017 || logging slow query | 0.000006 |+------------------------+-----------+

 
每行都是狀態變化的過程以及它們持續的時間。Status那一列和SHOW FULL PROCESSLIST的State應該是一致的。
這個值是來自於thd->proc_info變數。因此你所查看的這個值是直接來自MySQL內部的。儘管這些數值是比較直接易懂的，你也可以查看MySQL手冊。
 
你可以給SHOW PROFILES指定一個Query_ID來查看指定的語句，還可以給輸出添加新的列。如，查看使用者和CPU使用。可以用如下命令。
 

mysql> SHOW PROFILE CPU FOR QUERY 1;

 
SHOW PROFILE可以深入的查看伺服器執行語句的工作情況。以及也能協助你理解執行語句消耗時間的情況。一些限制是它沒有實現的功能，不能查看和剖析其他串連的語句，以及剖析時所引起的消耗。

SHOW PROFILES顯示最近發給伺服器的多條語句，條數根據會話變數profiling_history_size定義，預設是15，最大值為100。設為0等價於關閉分析功能。

SHOW PROFILE FOR QUERY n，這裡的n就是對應SHOW PROFILES輸出中的Query_ID。

例如：

mysql> show profiles;

+----------+-------------+---------------------------------------+| Query_ID | Duration | Query     |+----------+-------------+---------------------------------------+| 1 | 0.00037700 | alter table table1 drop column c3 int || 2 | 70.37123800 | alter table table1 drop column c3 || 3 | 0.00124500 | show tables    || 4 | 0.00569800 | select * from table1 where id=2 || 5 | 0.00068500 | select count(1) from tables1  || 6 | 0.00197900 | select count(1) from table1  || 7 | 0.00105900 | alter table tables1 drop c1  || 8 | 0.00800200 | alter table table1 drop c1  |+----------+-------------+---------------------------------------+8 rows in set (0.00 sec)

 

mysql> SHOW PROFILE FOR QUERY 2; #查看alter table table1 drop column c3的分析

+------------------------------+-----------+| Status   | Duration |+------------------------------+-----------+| starting   | 0.000183 || checking permissions  | 0.000057 || checking permissions  | 0.000059 || init    | 0.000060 || Opening tables  | 0.000071 || System lock   | 0.000062 || setup   | 0.000080 || creating table  | 0.005052 || After create   | 0.000220 || copy to tmp table  | 0.000244 || rename result table  | 70.364027 || end    | 0.000575 || Waiting for query cache lock | 0.000062 || end    | 0.000075 || query end   | 0.000057 || closing tables  | 0.000061 || freeing items  | 0.000080 || logging slow query  | 0.000056 || logging slow query  | 0.000098 || cleaning up   | 0.000059 |+------------------------------+-----------+20 rows in set (0.00 sec)

如果沒有指定FOR QUERY，那麼輸出最近一條語句的資訊。

LIMIT部分的用法與SELECT中LIMIT子句一致，不贅述。

type是可選的，取值範圍可以如下：

• ALL 顯示所有效能資訊
• BLOCK IO 顯示塊IO操作的次數
• CONTEXT SWITCHES 顯示環境切換次數，不管是主動還是被動
• CPU 顯示使用者CPU時間、系統CPU時間
• IPC 顯示發送和接收的訊息數量
• MEMORY [暫未實現]
• PAGE FAULTS 顯示頁錯誤數量
• SOURCE 顯示源碼中的函數名稱與位置
• SWAPS 顯示SWAP的次數

例：

mysql> show profile cpu for query 2;

+------------------------------+-----------+----------+------------+| Status   | Duration | CPU_user | CPU_system |+------------------------------+-----------+----------+------------+| starting   | 0.000183 | 0.000000 | 0.000000 || checking permissions  | 0.000057 | 0.000000 | 0.000000 || checking permissions  | 0.000059 | 0.000000 | 0.000000 || init    | 0.000060 | 0.000000 | 0.000000 || Opening tables  | 0.000071 | 0.000000 | 0.000000 || System lock   | 0.000062 | 0.000000 | 0.000000 || setup   | 0.000080 | 0.000000 | 0.001000 || creating table  | 0.005052 | 0.003000 | 0.001000 || After create   | 0.000220 | 0.000000 | 0.000000 || copy to tmp table  | 0.000244 | 0.000000 | 0.000000 || rename result table  | 70.364027 | 7.470864 | 41.612674 || end    | 0.000575 | 0.000000 | 0.001000 || Waiting for query cache lock | 0.000062 | 0.000000 | 0.000000 || end    | 0.000075 | 0.000000 | 0.000000 || query end   | 0.000057 | 0.000000 | 0.000000 || closing tables  | 0.000061 | 0.000000 | 0.000000 || freeing items  | 0.000080 | 0.000000 | 0.000000 || logging slow query  | 0.000056 | 0.000000 | 0.000000 || logging slow query  | 0.000098 | 0.000000 | 0.000000 || cleaning up   | 0.000059 | 0.000000 | 0.000000 |+------------------------------+-----------+----------+------------+20 rows in set (0.00 sec)

ps:
SHOW PROFILE ALL FOR QUERY 2;的資訊還可以通過SELECT * FROM information_schema.profiling WHERE query_id = 2 ORDER BY seq;擷取。

作用範圍
這個命令只是在本會話內起作用，即無法分析本會話外的語句。

開啟分析功能後，所有本會話中的語句都被分析（甚至包括執行錯誤的語句），除了SHOW PROFILE和SHOW PROFILES兩句本身。

應用樣本：使用SHOW PROFILE分析查詢快取命中的效能優勢。

mysql> set profiling=1;

Query OK, 0 rows affected (0.00 sec)

 

mysql> select count(1) as cnt from tran_excution;

+-------+| cnt |+-------+| 14225 |+-------+1 row in set (0.00 sec)

由於已經啟用了查詢快取，相同查詢（非分區表）可以直接在查詢快取中命中。

mysql> select count(1) as cnt from tran_excution;

我們仔細看下兩個同樣的語句的分析。

mysql> show profile source for query 1;

+--------------------------------+----------+-----------------------+---------------+-------------+| Status    | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+---------------+-------------+| starting   | 0.000048 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000013 | try_lock  | sql_cache.cc |  454 || checking query cache for query | 0.000040 | send_result_to_client | sql_cache.cc | 1561 || checking permissions  | 0.000023 | check_access  | sql_parse.cc | 4751 || Opening tables   | 0.000040 | open_tables  | sql_base.cc | 4831 || System lock   | 0.000020 | mysql_lock_tables | lock.cc |  299 || Waiting for query cache lock | 0.000037 | try_lock  | sql_cache.cc |  454 || init    | 0.000020 | mysql_select  | sql_select.cc | 2579 || optimizing   | 0.000015 | optimize  | sql_select.cc |  865 || statistics   | 0.000017 | optimize  | sql_select.cc | 1056 || preparing   | 0.000016 | optimize  | sql_select.cc | 1078 || executing   | 0.000015 | exec   | sql_select.cc | 1836 || Sending data   | 0.003875 | exec   | sql_select.cc | 2380 || end    | 0.000018 | mysql_select  | sql_select.cc | 2615 || query end   | 0.000015 | mysql_execute_command | sql_parse.cc | 4440 || closing tables   | 0.000016 | mysql_execute_command | sql_parse.cc | 4492 || freeing items   | 0.000016 | mysql_parse  | sql_parse.cc | 5640 || Waiting for query cache lock | 0.000012 | try_lock  | sql_cache.cc |  454 || freeing items   | 0.000032 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000017 | try_lock  | sql_cache.cc |  454 || freeing items   | 0.000016 | NULL   | NULL  | NULL || storing result in query cache | 0.000017 | end_of_result  | sql_cache.cc | 1020 || logging slow query  | 0.000018 | log_slow_statement | sql_parse.cc | 1461 || logging slow query  | 0.000050 | log_slow_statement | sql_parse.cc | 1470 || cleaning up   | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+---------------+-------------+25 rows in set (0.00 sec)

 

mysql> show profile source for query 2;

+--------------------------------+----------+-----------------------+--------------+-------------+| Status    | Duration | Source_function | Source_file | Source_line |+--------------------------------+----------+-----------------------+--------------+-------------+| starting   | 0.000051 | NULL   | NULL  | NULL || Waiting for query cache lock | 0.000014 | try_lock  | sql_cache.cc |  454 || checking query cache for query | 0.000016 | send_result_to_client | sql_cache.cc | 1561 || checking privileges on cached | 0.000013 | send_result_to_client | sql_cache.cc | 1652 || checking permissions  | 0.000015 | check_access  | sql_parse.cc | 4751 || sending cached result to clien | 0.000036 | send_result_to_client | sql_cache.cc | 1749 || logging slow query  | 0.000017 | log_slow_statement | sql_parse.cc | 1461 || cleaning up   | 0.000018 | dispatch_command | sql_parse.cc | 1417 |+--------------------------------+----------+-----------------------+--------------+-------------+8 rows in set (0.00 sec)

可以清晰地看到緩衝中命中時，大大節省了背景開銷。當然緩衝的使用也需要根據各種情境（表的資料規模，更新頻率等）考察使用，並不是啟用緩衝就一定能夠提高查詢效率。這裡僅僅作為SHOW PROFILE的一個應用樣本。