MySQL Query Profiler, 能夠查詢到此 SQL 語句會執行多少, 並看出 CPU/Memory 使用量, 執行過程 System lock, Table lock 花多少時間等等.從啓動Profile以後的全部查詢包括錯誤語句都會被記錄。mysql的sql語句優化也可使用explain,可是執行計劃是沒有辦法知道詳細的Memory/CPU等使用量。html
SHOW PROFILE [type [, type] ... ] [FOR QUERY n] [LIMIT row_count [OFFSET offset]]mysql
type: ALL | BLOCK IO | CONTEXT SWITCHES | CPU | IPC | MEMORY | PAGE FAULTS | SOURCE | SWAPSsql
Optional type values may be specified to display specific additional types of information:緩存
• ALL displays all information服務器
• BLOCK IO displays counts for block input and output operationsapp
• CONTEXT SWITCHES displays counts for voluntary and involuntary context switcheside
• CPU displays user and system CPU usage times優化
• IPC displays counts for messages sent and receivedspa
• MEMORY is not currently implemented線程
• PAGE FAULTS displays counts for major and minor page faults
• SOURCE displays the names of functions from the source code, together with the name and line number of the file in which the function occurs
• SWAPS displays swap counts
默認狀況下Mysql的profiling是關閉的,因此首先必須打開profiling
mysql> set profiling='on';
再查看變量:
mysql> show variables like '%profi%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling | ON |
| profiling_history_size | 15 | -- profiling_history_size記錄多少次查詢
+------------------------+-------+
2 rows in set (0.00 sec)
而後show profiles來查看query ID,而後使用這個query ID進行查詢分析。試例以下:
首先也打開了Query Profile,而後執行一條查詢語句:
mysql> show profiles;
+----------+------------+-------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-------------------------------+
| 1 | 0.00122000 | show variables like '%profi%' |
| 2 | 0.65738175 | show processlist |
| 3 | 0.00022550 | SELECT DATABASE() |
| 4 | 1.18196350 | select * from order_item |
+----------+------------+-------------------------------+
4 rows in set (0.59 sec)
mysql> show profile cpu, memory for query 4;
+--------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+--------------------+----------+----------+------------+
| starting | 0.055033 | NULL | NULL |
| Opening tables | 0.967959 | NULL | NULL |
| System lock | 0.000010 | NULL | NULL |
| Table lock | 0.000017 | NULL | NULL |
| init | 0.000121 | NULL | NULL |
| optimizing | 0.000007 | NULL | NULL |
| statistics | 0.000017 | NULL | NULL |
| preparing | 0.000014 | NULL | NULL |
| executing | 0.000006 | NULL | NULL |
| Sending data | 0.158729 | NULL | NULL |
| end | 0.000009 | NULL | NULL |
| query end | 0.000005 | NULL | NULL |
| freeing items | 0.000031 | NULL | NULL |
| logging slow query | 0.000003 | NULL | NULL |
| cleaning up | 0.000005 | NULL | NULL |
+--------------------+----------+----------+------------+
15 rows in set (0.59 sec)
mysql> show profile all for query 4;
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+-----------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+-----------------+-------------+
| starting | 0.055033 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | NULL | NULL | NULL |
| Opening tables | 0.967959 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_base.cc | 4483 |
| System lock | 0.000010 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\lock.cc | 258 |
| Table lock | 0.000017 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\lock.cc | 269 |
| init | 0.000121 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2354 |
| optimizing | 0.000007 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 771 |
| statistics | 0.000017 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 953 |
| preparing | 0.000014 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 963 |
| executing | 0.000006 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 1647 |
| Sending data | 0.158729 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2194 |
| end | 0.000009 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_select.cc | 2399 |
| query end | 0.000005 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 4822 |
| freeing items | 0.000031 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 5849 |
| logging slow query | 0.000003 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 1628 |
| cleaning up | 0.000005 | NULL | NULL | NULL | NULL | NULL | NULL | NULL |NULL | NULL | NULL | NULL | <unknown> | .\sql_parse.cc | 1595 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+--------
---------+-------------+
15 rows in set (0.00 sec)
每行都是狀態變化的過程以及它們持續的時間。
• QUERY_ID is a numeric statement identifier.
• SEQ is a sequence number indicating the display order for rows with the same QUERY_ID value.
• STATE is the profiling state to which the row measurements apply.
• DURATION indicates how long statement execution remained in the given state, in seconds.
• CPU_USER and CPU_SYSTEM indicate user and system CPU use, in seconds.
• CONTEXT_VOLUNTARY and CONTEXT_INVOLUNTARY indicate how many voluntary and involuntary context switches occurred.
• BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.
• MESSAGES_SENT and MESSAGES_RECEIVED indicate the number of communication messages sent and received.
• PAGE_FAULTS_MAJOR and PAGE_FAULTS_MINOR indicate the number of major and minor page faults.
• SWAPS indicates how many swaps occurred.
• SOURCE_FUNCTION, SOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.
Status是關於sql語句的狀態,和SHOW FULL PROCESSLIST顯示的State一致。關於sql語句狀態主要有如下幾種:
Checking table |
正在檢查數據表(這是自動的)。 |
Closing tables |
正在將表中修改的數據刷新到磁盤中,同時正在關閉已經用完的表。這是一個很快的操做,若是不是這樣的話,就應該確認磁盤空間是否已經滿了或者磁盤是否正處於重負中。 |
Connect Out |
複製從服務器正在鏈接主服務器 |
Copying to tmp table on disk |
因爲臨時結果集大於 tmp_table_size ,正在將臨時表從內存存儲轉爲磁盤存儲以此節省內存 |
Creating tmp table |
正在建立臨時表以存放部分查詢結果 |
deleting from main table |
服務器正在執行多表刪除中的第一部分,剛刪除第一個表。 |
deleting from reference tables |
服務器正在執行多表刪除中的第二部分,正在刪除其餘 表的記錄。 |
Flushing tables |
正在執行 FLUSH TABLES ,等待其餘線程關閉數據表 |
Killed |
發送了一個 kill 請求給某線程,那麼這個線程將會檢查 kill 標誌位,同時會放棄下一個 kill 請求。 MySQL 會在每次的主循環中檢查 kill 標誌位,不過有些狀況下該線程可能會過一小段才能死掉。若是該線程程被其餘線程鎖住了,那麼 kill 請求會在鎖釋放時立刻生效。 |
Locked |
被其餘查詢鎖住了 |
Sending data |
正在處理 SELECT 查詢的記錄,同時正在把結果發送給客戶端 |
Sorting for group |
正在爲 GROUP BY 作排序 |
Sorting for order |
正在爲 ORDER BY 作排序 |
Opening tables |
這個過程應該會很快,除非受到其餘因素的干擾。例如,在執 ALTER TABLE 或 LOCK TABLE 語句行完之前,數據表沒法被其餘線程打開。 正嘗試打開一個表 |
Removing duplicates |
正在執行一個 SELECT DISTINCT 方式的查詢,可是 MySQL 沒法在前一個階段優化掉那些重複的記錄。所以, MySQL 須要再次去掉重複的記錄,而後再把結果發送給客戶端 |
Reopen table |
得到了對一個表的鎖,可是必須在表結構修改以後才能得到這個鎖。已經釋放鎖,關閉數據表,正嘗試從新打開數據表 |
Repair by sorting |
修復指令正在排序以建立索引 |
Repair with keycache |
修復指令正在利用索引緩存一個一個地建立新索引。它會比 Repair by sorting 慢些 |
Searching rows for update |
正在講符合條件的記錄找出來以備更新。它必須在 UPDATE 要修改相關的記錄以前就完成了 |
Sleeping |
正在等待客戶端發送新請求 |
System lock |
正在等待取得一個外部的系統鎖。若是當前沒有運行多個 mysqld 服務器同時請求同一個表,那麼能夠經過增長 --skip-external-locking 參數來禁止外部系統鎖 |
Upgrading lock |
INSERT DELAYED 正在嘗試取得一個鎖表以插入新記錄 |
Updating |
正在搜索匹配的記錄,而且修改它們 |
User Lock |
正在等待 GET_LOCK() |
Waiting for tables |
該線程獲得通知,數據表結構已經被修改了,須要從新打開數據表以取得新的結構。而後,爲了能的從新打開數據表,必須等到全部其餘線程關閉這個表。如下幾種狀況下會產生這個通知: FLUSH TABLES tbl_name, ALTER TABLE, RENAME TABLE, REPAIR TABLE, ANALYZE TABLE, 或 OPTIMIZE TABLE |
waiting for handler insert |
INSERT DELAYED 已經處理完了全部待處理的插入操做,正在等待新的請求 |