分析SQL執行帶來的開銷是優化SQL的重要手段。在MySQL數據庫中，可以通過配置profiling參數來啟用SQL剖析。該參數可以在全局和session級別來設置。對于全局級別則作用于整個MySQL實例，而session級別緊影響當前session。該參數開啟后，后續執行的SQL語句都將記錄其資源開銷，諸如IO，上下文切換，CPU，Memory等等。根據這些開銷進一步分析當前SQL瓶頸從而進行優化與調整。本文描述了如何使用MySQL profile，不涉及具體的樣例分析。
1、有關profile的描述
復制代碼代碼如下:
--當前版本
root@localhost[sakila]> show variables like 'version';
+---------------+---------------------------------------+
| Variable_name | Value |
+---------------+---------------------------------------+
| version | 5.6.17-enterprise-commercial-advanced |
+---------------+---------------------------------------+
--查看profiling系統變量
root@localhost[sakila]> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES | --只讀變量，用于控制是否由系統變量開啟或禁用profiling
| profiling | OFF | --開啟SQL語句剖析功能
| profiling_history_size | 15 | --設置保留profiling的數目，缺省為15，范圍為0至100，為0時將禁用profiling
+------------------------+-------+
profiling [539]
If set to 0 or OFF (the default), statement profiling is disabled. If set to 1 or ON, statement prof
is enabled and the SHOW PROFILE and SHOW PROFILES statements provide access to prof
information. See Section 13.7.5.32, “SHOW PROFILES Syntax”.
This variable is deprecated in MySQL 5.6.8 and will be removed in a future MySQL release.
profiling_history_size [539]
The number of statements for which to maintain profiling information if profiling [539] is
enabled. The default value is 15. The maximum value is 100. Setting the value to 0 effectively
disables profiling. See Section 13.7.5.32, “SHOW PROFILES Syntax”.
This variable is deprecated in MySQL 5.6.8 and will be removed in a future MySQL release.
--獲取profile的幫助
root@localhost[sakila]> help profile;
Name: 'SHOW PROFILE'
Description:
Syntax:
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]
type:
ALL --顯示所有的開銷信息
| BLOCK IO --顯示塊IO相關開銷
| CONTEXT SWITCHES --上下文切換相關開銷
| CPU --顯示CPU相關開銷信息
| IPC --顯示發送和接收相關開銷信息
| MEMORY --顯示內存相關開銷信息
| PAGE FAULTS --顯示頁面錯誤相關開銷信息
| SOURCE --顯示和Source_function，Source_file，Source_line相關的開銷信息
| SWAPS --顯示交換次數相關開銷的信息
The SHOW PROFILE and SHOW PROFILES statements display profiling
information that indicates resource usage for statements executed
during the course of the current session.
*Note*: These statements are deprecated as of MySQL 5.6.7 and will be
removed in a future MySQL release. Use the Performance Schema instead;
see http://dev.mysql.com/doc/refman/5.6/en/performance-schema.html.
--上面描述從5.6.7開始該命令將會被移除，用Performance Schema instead代替
--在Oracle數據庫中，是通過autotrace來剖析單條SQL并獲取真實的執行計劃以及其開銷信息
2、開啟porfiling
復制代碼代碼如下:
--啟用session級別的profiling
root@localhost[sakila]> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
--驗證修改后的結果
root@localhost[sakila]> show variables like '%profil%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | ON |
| profiling_history_size | 15 |
+------------------------+-------+
--發布SQL查詢
root@localhost[sakila]> select count(*) from customer;
+----------+
| count(*) |
+----------+
| 599 |
+----------+
--查看當前session所有已產生的profile
root@localhost[sakila]> show profiles;
+----------+------------+--------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------+
| 1 | 0.00253600 | show variables like '%profil%' |
| 2 | 0.00138150 | select count(*) from customer |
+----------+------------+--------------------------------+
2 rows in set, 1 warning (0.01 sec)
--我們看到有2個warning，之前一個，現在一個
root@localhost[sakila]> show warnings; --下面的結果表明SHOW PROFILES將來會被Performance Schema替換掉
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Level | Code | Message |
+---------+------+--------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | 'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead |
+---------+------+--------------------------------------------------------------------------------------------------------------+
3、獲取SQL語句的開銷信息
復制代碼代碼如下:
--可以直接使用show profile來查看上一條SQL語句的開銷信息
--注，show profile之類的語句不會被profiling，即自身不會產生Profiling
--我們下面的這個show profile查看的是show warnings產生的相應開銷
root@localhost[sakila]> show profile;
+----------------+----------+
| Status | Duration |
+----------------+----------+
| starting | 0.000141 |
| query end | 0.000058 |
| closing tables | 0.000014 |
| freeing items | 0.001802 |
| cleaning up | 0.000272 |
+----------------+----------+
--如下面的查詢show warnings被添加到profiles
root@localhost[sakila]> show profiles;
+----------+------------+--------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------+
| 1 | 0.00253600 | show variables like '%profil%' |
| 2 | 0.00138150 | select count(*) from customer |
| 3 | 0.00228600 | show warnings |
+----------+------------+--------------------------------+
--獲取指定查詢的開銷
root@localhost[sakila]> show profile for query 2;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000148 |
| checking permissions | 0.000014 |
| Opening tables | 0.000047 |
| init | 0.000023 |
| System lock | 0.000035 |
| optimizing | 0.000012 |
| statistics | 0.000019 |
| preparing | 0.000014 |
| executing | 0.000006 |
| Sending data | 0.000990 |
| end | 0.000010 |
| query end | 0.000011 |
| closing tables | 0.000010 |
| freeing items | 0.000016 |
| cleaning up | 0.000029 |
+----------------------+----------+
--查看特定部分的開銷，如下為CPU部分的開銷
root@localhost[sakila]> show profile cpu for query 2 ;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting | 0.000148 | 0.000000 | 0.000000 |
| checking permissions | 0.000014 | 0.000000 | 0.000000 |
| Opening tables | 0.000047 | 0.000000 | 0.000000 |
| init | 0.000023 | 0.000000 | 0.000000 |
| System lock | 0.000035 | 0.000000 | 0.000000 |
| optimizing | 0.000012 | 0.000000 | 0.000000 |
| statistics | 0.000019 | 0.000000 | 0.000000 |
| preparing | 0.000014 | 0.000000 | 0.000000 |
| executing | 0.000006 | 0.000000 | 0.000000 |
| Sending data | 0.000990 | 0.001000 | 0.000000 |
| end | 0.000010 | 0.000000 | 0.000000 |
| query end | 0.000011 | 0.000000 | 0.000000 |
| closing tables | 0.000010 | 0.000000 | 0.000000 |
| freeing items | 0.000016 | 0.000000 | 0.000000 |
| cleaning up | 0.000029 | 0.000000 | 0.000000 |
+----------------------+----------+----------+------------+
--如下為MEMORY部分的開銷
root@localhost[sakila]> show profile memory for query 2 ;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000148 |
| checking permissions | 0.000014 |
| Opening tables | 0.000047 |
| init | 0.000023 |
| System lock | 0.000035 |
| optimizing | 0.000012 |
| statistics | 0.000019 |
| preparing | 0.000014 |
| executing | 0.000006 |
| Sending data | 0.000990 |
| end | 0.000010 |
| query end | 0.000011 |
| closing tables | 0.000010 |
| freeing items | 0.000016 |
| cleaning up | 0.000029 |
+----------------------+----------+
--同時查看不同資源開銷
root@localhost[sakila]> show profile block io,cpu for query 2;
+----------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000148 | 0.000000 | 0.000000 | 0 | 0 |
| checking permissions | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |
| Opening tables | 0.000047 | 0.000000 | 0.000000 | 0 | 0 |
| init | 0.000023 | 0.000000 | 0.000000 | 0 | 0 |
| System lock | 0.000035 | 0.000000 | 0.000000 | 0 | 0 |
| optimizing | 0.000012 | 0.000000 | 0.000000 | 0 | 0 |
| statistics | 0.000019 | 0.000000 | 0.000000 | 0 | 0 |
| preparing | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |
| executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 |
| Sending data | 0.000990 | 0.001000 | 0.000000 | 0 | 0 |
| end | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |
| query end | 0.000011 | 0.000000 | 0.000000 | 0 | 0 |
| closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |
| freeing items | 0.000016 | 0.000000 | 0.000000 | 0 | 0 |
| cleaning up | 0.000029 | 0.000000 | 0.000000 | 0 | 0 |
+----------------------+----------+----------+------------+--------------+---------------+
--下面的SQL語句用于查詢query_id為2的SQL開銷，且按最大耗用時間倒序排列
root@localhost[sakila]> set @query_id=2;
root@localhost[sakila]> 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.000990 | 71.53 | 1 | 0.0009900000 |--最大耗用時間部分為發送數據
| starting | 0.000148 | 10.69 | 1 | 0.0001480000 |
| Opening tables | 0.000047 | 3.40 | 1 | 0.0000470000 |
| System lock | 0.000035 | 2.53 | 1 | 0.0000350000 |
| cleaning up | 0.000029 | 2.10 | 1 | 0.0000290000 |
| init | 0.000023 | 1.66 | 1 | 0.0000230000 |
| statistics | 0.000019 | 1.37 | 1 | 0.0000190000 |
| freeing items | 0.000016 | 1.16 | 1 | 0.0000160000 |
| preparing | 0.000014 | 1.01 | 1 | 0.0000140000 |
| checking permissions | 0.000014 | 1.01 | 1 | 0.0000140000 |
| optimizing | 0.000012 | 0.87 | 1 | 0.0000120000 |
| query end | 0.000011 | 0.79 | 1 | 0.0000110000 |
| end | 0.000010 | 0.72 | 1 | 0.0000100000 |
| closing tables | 0.000010 | 0.72 | 1 | 0.0000100000 |
| executing | 0.000006 | 0.43 | 1 | 0.0000060000 |
+----------------------+----------+-------+-------+--------------+
--開啟profiling后，我們可以通過show profile等方式查看，其實質是這些開銷信息被記錄到information_schema.profiling表
--如下面的查詢，部分信息省略
profiling
root@localhost[information_schema]> select * from profiling limit 3,3/G;
*************************** 1. row ***************************
QUERY_ID: 1
SEQ: 5
STATE: init
DURATION: 0.000020
CPU_USER: 0.000000
CPU_SYSTEM: 0.000000
CONTEXT_VOLUNTARY: 0
CONTEXT_INVOLUNTARY: 0
BLOCK_OPS_IN: 0
BLOCK_OPS_OUT: 0
MESSAGES_SENT: 0
MESSAGES_RECEIVED: 0
PAGE_FAULTS_MAJOR: 0
PAGE_FAULTS_MINOR: 0
SWAPS: 0
SOURCE_FUNCTION: mysql_prepare_select
SOURCE_FILE: sql_select.cc
SOURCE_LINE: 1050
--停止profile,可以設置profiling參數，或者在session退出之后,profiling會被自動關閉
root@localhost[sakila]> set profiling=off;
Query OK, 0 rows affected, 1 warning (0.00 sec)
