show profile是由Jeremy Cole捐獻給MySQL社區版本的。默認的是關閉的，但是會話級別可以開啟這個功能。開啟它可以讓MySQL收集在執行語句的時候所使用的資源。為了統計報表,把profiling設為1
|
1
|
mysql>
SET
profiling = 1;
|
之后在運行一個查詢
|
1
2
3
4
5
6
7
|
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進行查看。
|
1
|
mysql> SHOW PROFILES\G
|
|
1
2
3
4
|
*************************** 1. row ***************************
Query_ID: 1
Duration: 0.02596900
Query: SELECT COUNT(DISTINCT actor.first_name) AS cnt_name,...
|
你可以使用SHOW PROFILE語句來獲取已經存儲的剖析數據。如果不加參數，會顯示狀態以及它們持續的時間。
|
1
|
mysql> SHOW PROFILE;
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
|
+------------------------+-----------+
| 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使用。可以用如下命令。
|
1
|
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。
例如：
|
1
|
mysql> show profiles;
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
|
+----------+-------------+---------------------------------------+
| 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)
|
|
1
|
mysql> SHOW PROFILE
FOR
QUERY 2; #查看
alter
table
table1
drop
column
c3的分析
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
|
+------------------------------+-----------+
| 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的次數
例：
|
1
|
mysql> show profile cpu
for
query 2;
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
|
+------------------------------+-----------+----------+------------+
| 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分析查詢緩存命中的性能優勢。
|
1
|
mysql>
set
profiling=1;
|
|
1
|
Query OK, 0 rows affected (0.00 sec)
|
|
1
|
mysql>
select
count
(1)
as
cnt
from
tran_excution;
|
|
1
2
3
4
5
6
|
+-------+
| cnt |
+-------+
| 14225 |
+-------+
1 row in set (0.00 sec)
|
由於已經啟用了查詢緩存，相同查詢（非分區表）可以直接在查詢緩存中命中。
|
1
|
mysql>
select
count
(1)
as
cnt
from
tran_excution;
|
我們仔細看下兩個同樣的語句的分析。
|
1
|
mysql> show profile source
for
query 1;
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
|
+--------------------------------+----------+-----------------------+---------------+-------------+
| 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)
|
|
1
|
mysql> show profile source
for
query 2;
|
|
1
2
3
4
5
6
7
8
9
10
11
12
13
|
+--------------------------------+----------+-----------------------+--------------+-------------+
| 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的一個應用示例。