INFORMATION_SCHEMA.PROFILING_ZenDei技術網路在線

INFORMATION_SCHEMA PROFILING "Table" PROFILING表提供了語句分析信息。其內容對應於SHOW PROFILES和SHOW PROFILE語句生成的信息. INFORMATION_SCHEMA Name|SHOW Name| Notes |: |: QUER ...

INFORMATION_SCHEMA PROFILING Table

PROFILING表提供了語句分析信息。其內容對應於SHOW PROFILES和SHOW PROFILE語句生成的信息.

INFORMATION_SCHEMA Name	SHOW Name	Notes
QUERY_ID	Query_ID	標識
SEQ		具有相同QUERY_ID值的行的顯示順序的序列號
STATE	Status	行測量適用的分析狀態
DURATION	Duration	在給定狀態下，多長時間的語句執行保持在幾秒鐘內
CPU_USER	CPU_user	用戶CPU使用，以秒為單位
CPU_SYSTEM	CPU_system	系統CPU使用，以秒為單位
CONTEXT_VOLUNTARY	Context_voluntary	自願上下文切換髮生
CONTEXT_INVOLUNTARY	Context_involuntary	非自願上下文切換髮生
BLOCK_OPS_IN	Block_ops_in	輸入塊操作的數量
BLOCK_OPS_OUT	Block_ops_out	輸出塊操作的數量
MESSAGES_SENT	Messages_sent	發送的通信消息的數量
MESSAGES_RECEIVED	Messages_received	接收的通信消息的數量
PAGE_FAULTS_MAJOR	Page_faults_major	主頁面錯誤的數量
PAGE_FAULTS_MINOR	Page_faults_minor	次頁面錯誤的數量
SWAPS	Swaps	發生了多少次交換
SOURCE_FUNCTION	Source_function	源代碼執行分析狀態的位置的信息
SOURCE_FILE	Source_file	源代碼執行分析狀態的位置的信息
SOURCE_LINE	Source_line	源代碼執行分析狀態的位置的信息

13.7.5.31 SHOW PROFILES Syntax

SHOW PROFILES

SHOW PROFILES語句與SHOW PROFILE一起顯示分析信息，指示在當前會話過程中執行的語句的資源使用情況。

13.7.5.30 SHOW PROFILE Syntax

SHOW PROFILE [type [, type] ... ]
    [FOR QUERY n]
    [LIMIT row_count [OFFSET offset]]

type:
    ALL
  | BLOCK IO
  | CONTEXT SWITCHES
  | CPU
  | IPC
  | MEMORY
  | PAGE FAULTS
  | SOURCE
  | SWAPS

可以指定可選類型值以顯示特定的其他類型的信息（對應PROFILING中欄位）：

type	note
ALL	顯示所有信息
BLOCK IO	顯示塊輸入和輸出操作的計數
CONTEXT SWITCHES	顯示自願和非自願上下文切換的計數
CPU	顯示用戶和系統CPU使用時間
IPC	顯示發送和接收消息的計數
MEMORY	目前尚未實施
PAGE FAULTS	顯示主頁和次頁錯誤的計數
SOURCE	顯示來自源代碼的函數的名稱以及該函數發生的文件的名稱和行號
SWAPS	顯示交換計數

SHOW PROFILE和SHOW PROFILES語句顯示分析信息，指示在當前會話過程中執行的語句的資源使用情況。

Profiling由Profiling會話變數控制，預設值為0（OFF）。通過將Profiling設置為1或ON可啟用分析：

mysql> SET profiling = 1;

SHOW PROFILES顯示發送到伺服器的最新語句的列表。列表的大小由profiling_history_size會話變數控制，該變數的預設值為15.最大值為100.將值設置為0具有禁用性能分析的實際效果。

除SHOW PROFILE和SHOW PROFILES之外，所有語句都進行了概要分析，因此您將不會在配置文件列表中找到這些語句。對於格式錯誤的執行語句，例如SHOW PROFILING是一個非法語句，如果您嘗試執行該語句，則會出現語法錯誤，但會顯示在概要分析列表中。

SHOW PROFILE顯示有關單個語句的詳細信息，如果沒有追加FOR QUERY n子句，輸出與最近執行的語句相關；否則展示特定語句的信息。 n的值對應於SHOW PROFILES顯示的Query_ID值。

可以給出LIMIT row_count子句以將輸出限製為row_count行。如果給定了LIMIT，則可以添加OFFSET偏移以將輸出偏移行開始到整組行。

預設情況下，SHOW PROFILE顯示狀態和持續時間列。

每個會話啟用分析。會話結束時，其分析信息丟失。

說了那麼多，上面這些已經被廢棄啦！！！！

Note:

這些語句已被逐漸棄用，將在未來的MySQL版本中被刪除。

也就是說新版本包括以後的版本對於性能的監控逐漸使用PERFORMANCE_SCHEM代替INFORMATION_SCHEMA -->詳見Chapter 25 MySQL Performance Schema

Action

已知：

mysql root@127.0.0.1:nt> SELECT * FROM student
+------+--------+-------+-------+
|   id | name   |   age | sex   |
|------+--------+-------+-------|
|    1 | s1     |    12 | m     |
|    2 | s2     |    12 | w     |
|    3 | s3     |    11 | w     |
+------+--------+-------+-------+
3 rows in set
Time: 0.004s
mysql root@127.0.0.1:nt> SELECT * FROM teacher
+------+--------+
|   id | name   |
|------+--------|
|    1 | Han    |
|    2 | Gou    |
|    3 | Eric   |
+------+--------+
3 rows in set
Time: 0.002s
mysql root@127.0.0.1:nt> SELECT * FROM course
+------+--------------+----------------+
|   id |   teacher_id | name           |
|------+--------------+----------------|
|    1 |            1 | Advanced Maths |
|    2 |            2 | English        |
|    3 |            3 | Arts           |
|    4 |            1 | Physics        |
|    5 |            3 | Programming    |
+------+--------------+----------------+
5 rows in set
Time: 0.003s
mysql root@127.0.0.1:nt> SELECT * FROM score
+--------------+-------------+---------+
|   student_id |   course_id |   score |
|--------------+-------------+---------|
|            1 |           1 |      78 |
|            1 |           2 |      56 |
|            1 |           3 |      89 |
|            1 |           4 |      60 |
|            1 |           5 |      92 |
|            2 |           1 |      92 |
|            2 |           2 |      60 |
|            2 |           3 |      78 |
|            2 |           4 |      77 |
|            2 |           5 |      95 |
|            3 |           1 |      66 |
|            3 |           2 |      50 |
|            3 |           3 |      78 |
|            3 |           4 |      67 |
|            3 |           5 |      86 |
+--------------+-------------+---------+
15 rows in set
Time: 0.003s

解：高數比美術分數高的學生信息

SELECT S.* 
FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
     (SELECT SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B, 
     student S 
WHERE A.STUDENT_ID=B.STUDENT_ID 
AND   A.COURSE_ID=1 
AND   B.COURSE_ID=3 
AND   A.SCORE>B.SCORE 
AND   A.STUDENT_ID=S.ID;

mysql [email protected]:nt> SELECT @@profiling
+---------------+
|   @@profiling |
|---------------|
|             0 |
+---------------+
1 row in set
Time: 0.002s
mysql [email protected]:nt> SET profiling = 1
Query OK, 0 rows affected
Time: 0.001s
mysql [email protected]:nt> SELECT S.*
                      -> FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
                      ->      (SELECT SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B,
                      ->      student S
                      -> WHERE A.STUDENT_ID=B.STUDENT_ID
                      -> AND   A.COURSE_ID=1
                      -> AND   B.COURSE_ID=3
                      -> AND   A.SCORE>B.SCORE
                      -> AND   A.STUDENT_ID=S.ID;
+------+--------+-------+-------+
|   id | name   |   age | sex   |
|------+--------+-------+-------|
|    2 | s2     |    12 | w     |
+------+--------+-------+-------+
1 row in set
Time: 0.007s
mysql [email protected]:nt> SHOW PROFILES
+------------+------------+---------------+
|   Query_ID |   Duration | Query         |
|------------+------------+---------------|
|          1 |   4.5e-05  | SHOW WARNINGS |
|          2 |   0.000603 | SELECT S.*
FROM (SELECT SC1.STUDENT_ID,SC1.COURSE_ID,SC1.SCORE FROM score SC1) A,
     (SELECT SC2.STUDENT_ID,SC2.COURSE_ID,SC2.SCORE FROM score SC2) B,
     student S
WHERE A.STUDENT_ID=B.STUDENT_ID
AND   A.COURSE_ID=1
AND   B.COURSE_ID=3
AND   A.SCORE>B.SCORE
AND   A.STUDENT_ID=S.ID               |
+------------+------------+---------------+
2 rows in set
Time: 0.002s
mysql [email protected]:nt> SHOW PROFILE FOR QUERY 2
+----------------------+------------+
| Status               |   Duration |
|----------------------+------------|
| starting             |   0.000134 |
| checking permissions |   1.1e-05  |
| checking permissions |   4e-06    |
| checking permissions |   7e-06    |
| Opening tables       |   2.4e-05  |
| init                 |   5.2e-05  |
| System lock          |   1.1e-05  |
| optimizing           |   1.5e-05  |
| statistics           |   0.000161 |
| preparing            |   2.7e-05  |
| executing            |   4e-06    |
| Sending data         |   6.4e-05  |
| end                  |   6e-06    |
| query end            |   7e-06    |
| closing tables       |   8e-06    |
| freeing items        |   5.4e-05  |
| cleaning up          |   1.4e-05  |
+----------------------+------------+
17 rows in set
Time: 0.005s

上面的結果太醜

mysql [email protected]:nt> set @query_id=2
Query OK, 0 rows affected
Time: 0.001s

使用下麵的SQL：

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(*) CALLS,
    SUM(DURATION)/COUNT(*) AS "R/CALL"
FROM information_schema.PROFILING
WHERE QUERY_ID=@query_id
GROUP BY STATE
ORDER BY TOTAL_R DESC;

mycli執行上面的sql：

+----------------------+-----------+---------+---------+------------+
| STATE                |   TOTAL_R |   PCT_R |   CALLS |     R/CALL |
|----------------------+-----------+---------+---------+------------|
| statistics           |  0.000161 |   26.7  |       1 | 0.000161   |
| starting             |  0.000134 |   22.22 |       1 | 0.000134   |
| Sending data         |  6.4e-05  |   10.61 |       1 | 6.4e-05    |
| freeing items        |  5.4e-05  |    8.96 |       1 | 5.4e-05    |
| init                 |  5.2e-05  |    8.62 |       1 | 5.2e-05    |
| preparing            |  2.7e-05  |    4.48 |       1 | 2.7e-05    |
| Opening tables       |  2.4e-05  |    3.98 |       1 | 2.4e-05    |
| checking permissions |  2.2e-05  |    3.65 |       3 | 7.3333e-06 |
| optimizing           |  1.5e-05  |    2.49 |       1 | 1.5e-05    |
| cleaning up          |  1.4e-05  |    2.32 |       1 | 1.4e-05    |
| System lock          |  1.1e-05  |    1.82 |       1 | 1.1e-05    |
| closing tables       |  8e-06    |    1.33 |       1 | 8e-06      |
| query end            |  7e-06    |    1.16 |       1 | 7e-06      |
| end                  |  6e-06    |    1    |       1 | 6e-06      |
| executing            |  4e-06    |    0.66 |       1 | 4e-06      |
+----------------------+-----------+---------+---------+------------+
15 rows in set
Time: 0.018s

可以看出來，時間消耗占比最高依次：

statistics：伺服器正在計算統計信息以開發查詢執行計劃。如果一個線程長時間處於這種狀態，伺服器可能是磁碟綁定的，執行其他工作
starting
Sending data：線程正在讀取和處理SELECT語句的行，並向客戶端發送數據。由於在此狀態期間發生的操作往往執行大量的磁碟訪問（讀取），所以在給定查詢的整個生命周期內通常是最長的運行狀態
freeing items：線程已經執行了一個命令。在這種狀態下完成的項目的一些釋放涉及查詢緩存。這種狀態通常是清理
init：這發生在ALTER TABLE，DELETE，INSERT，SELECT或UPDATE語句的初始化之前。處於此狀態的伺服器採取的操作包括刷新二進位日誌，InnoDB日誌和一些查詢緩存清理操作。

對於最終狀態，可能會發生以下操作：

在表中的數據更改後刪除查詢緩存條目
將事件寫入二進位日誌
釋放記憶體緩衝區，包括Blob

下麵看看記錄2對應的CPU信息

mysql [email protected]:nt> SHOW PROFILE CPU FOR QUERY 2
+----------------------+------------+------------+--------------+
| Status               |   Duration |   CPU_user |   CPU_system |
|----------------------+------------+------------+--------------|
| starting             |   0.000134 |   0.000126 |      8e-06   |
| checking permissions |   1.1e-05  |   4e-06    |      6e-06   |
| checking permissions |   4e-06    |   2e-06    |      3e-06   |
| checking permissions |   7e-06    |   4e-06    |      2e-06   |
| Opening tables       |   2.4e-05  |   2.3e-05  |      2e-06   |
| init                 |   5.2e-05  |   4.8e-05  |      3e-06   |
| System lock          |   1.1e-05  |   8e-06    |      2e-06   |
| optimizing           |   1.5e-05  |   1.4e-05  |      2e-06   |
| statistics           |   0.000161 |   0.000113 |      5.3e-05 |
| preparing            |   2.7e-05  |   1.9e-05  |      3e-06   |
| executing            |   4e-06    |   2e-06    |      3e-06   |
| Sending data         |   6.4e-05  |   6.3e-05  |      1e-06   |
| end                  |   6e-06    |   3e-06    |      3e-06   |
| query end            |   7e-06    |   5e-06    |      1e-06   |
| closing tables       |   8e-06    |   7e-06    |      1e-06   |
| freeing items        |   5.4e-05  |   1.3e-05  |      4.2e-05 |
| cleaning up          |   1.4e-05  |   1.2e-05  |      2e-06   |
+----------------------+------------+------------+--------------+
17 rows in set
Time: 0.009s

INFORMATION_SCHEMA.PROFILING

INFORMATION_SCHEMA PROFILING Table

13.7.5.31 SHOW PROFILES Syntax

13.7.5.30 SHOW PROFILE Syntax

Note:

Action

Qs:為什麼show profiles結果中的duration和直接執行的時間差距那麼大？