MySQL Query Profile

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 已經處理完了全部待處理的插入操做,正在等待新的請求

 

http://dev.mysql.com/doc/refman/5.1/en/show-profile.html

相關文章
相關標籤/搜索