分析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
+------------------------+-------+
--擷取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 --顯示交換次數相關開銷的資訊
--上面描述從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) 這裡還需要注意一點就是，需要安裝profile子產品才能實作。
1、不過版本要在5.0.37之後。(SHOW PROFILES and SHOW PROFILE were added in MySQL 5.0.37.)
SELECT @@profiling; 來檢視是否已經啟用profile，如果profilng值為0，可以通過
SET profiling = 1; 來啟用。啟用profiling之後，我們執行一條查詢語句，比如：
select count(*) from roi_summary; 然後show profiles檢視如下：
+----------------+------------+----------------------------------+
| Query_ID | Duration | Query |
+----------------+------------+----------------------------------+
| 1 | 0.00021500 | select @@profiling |
| 2 | 0.05522700 | select count(*) from roi_summary |
+----------------+------------+----------------------------------+ 2 rows in set (0.00 sec)
其中ID為5的語句是剛執行的查詢語句
2、變量profiling是使用者變量，每次都得重新啟用。
以下是我做的一些實驗。資料很明顯，就不多解釋了。
mysql> use test
Database changed
mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)
mysql> show tables;
+----------------+
| Tables_in_test |
+----------------+
| bag_item |
| bag_user |
| score |
| t |
+----------------+
4 rows in set (0.03 sec)
mysql> select count(*) from t;
+----------+
| count(*) |
+----------+
| 2097152 |
+----------+
1 row in set (0.74 sec)
mysql> show profiles;
+----------+------------+------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------+
| 1 | 0.02717000 | show tables |
| 2 | 0.74770100 | select count(*) from t |
+----------+------------+------------------------+
2 rows in set (0.00 sec)
mysql> show profile for query 2;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| (initialization) | 0.000004 |
| checking query cache for query | 0.000044 |
| Opening tables | 0.000012 |
| System lock | 0.000017 |
| Table lock | 0.00003 |
| init | 0.000013 |
| optimizing | 0.000008 |
| statistics | 0.000013 |
| preparing | 0.000011 |
| executing | 0.000006 |
| Sending data | 0.747313 |
| end | 0.000014 |
| query end | 0.000006 |
| storing result in query cache | 0.000006 |
| freeing items | 0.000012 |
| closing tables | 0.000009 |
| logging slow query | 0.000183 |
+--------------------------------+----------+
17 rows in set (0.00 sec)
mysql> show profile block io,cpu for query 2;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| (initialization) | 0.000004 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000044 | 0 | 0 | 0 | 0 |
| Opening tables | 0.000012 | 0 | 0 | 0 | 0 |
| System lock | 0.000017 | 0 | 0 | 0 | 0 |
| Table lock | 0.00003 | 0 | 0 | 0 | 0 |
| init | 0.000013 | 0 | 0 | 0 | 0 |
| optimizing | 0.000008 | 0 | 0 | 0 | 0 |
| statistics | 0.000013 | 0 | 0 | 0 | 0 |
| preparing | 0.000011 | 0 | 0 | 0 | 0 |
| executing | 0.000006 | 0 | 0 | 0 | 0 |
| Sending data | 0.747313 | 0.746887 | 0 | 0 | 0 |
| end | 0.000014 | 0 | 0 | 0 | 0 |
| query end | 0.000006 | 0 | 0 | 0 | 0 |
| storing result in query cache | 0.000006 | 0 | 0 | 0 | 0 |
| freeing items | 0.000012 | 0 | 0 | 0 | 0 |
| closing tables | 0.000009 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000183 | 0 | 0 | 0 | 0 |
+--------------------------------+----------+----------+------------+--------------+---------------+
17 rows in set (0.00 sec)
mysql> insert into t(username) select username from t;
Query OK, 2097152 rows affected (34.17 sec)
Records: 2097152 Duplicates: 0 Warnings: 0
mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+------------------------------------------------+
| 1 | 0.02717000 | show tables |
| 2 | 0.74770100 | select count(*) from t |
| 3 | 0.00004200 | show prifile for query 2 |
| 4 | 34.30410100 | insert into t(username) select username from t |
+----------+-------------+------------------------------------------------+
4 rows in set (0.00 sec)
mysql> show profile cpu,block io,memory,swaps for query 4;
mysql> select count(*) from t;
+----------+
| count(*) |
+----------+
| 4194304 |
+----------+
1 row in set (1.51 sec)
mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+------------------------------------------------+
| 1 | 0.02717000 | show tables |
| 2 | 0.74770100 | select count(*) from t |
| 3 | 0.00004200 | show prifile for query 2 |
| 4 | 34.30410100 | insert into t(username) select username from t |
| 5 | 1.50563800 | select count(*) from t |
+----------+-------------+------------------------------------------------+
5 rows in set (0.00 sec)
mysql> show profile cpu,block io,memory,swaps,context switches,source for query 5;
……
mysql> update t set username = \'waill\';
Query OK, 4194304 rows affected (44.82 sec)
Rows matched: 4194304 Changed: 4194304 Warnings: 0
mysql> show profiles;
+----------+-------------+------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+------------------------------------------------+
| 1 | 0.02717000 | show tables |
| 2 | 0.74770100 | select count(*) from t |
| 3 | 0.00004200 | show prifile for query 2 |
| 4 | 34.30410100 | insert into t(username) select username from t |
| 5 | 1.50563800 | select count(*) from t |
| 6 | 44.82054700 | update t set username = \'waill\' |
+----------+-------------+------------------------------------------------+
6 rows in set (0.00 sec)
mysql> show profile cpu,block io,memory,swaps,context switches,source for query 6; 