MySQL使用profile分析語句效能消耗

dbasdk發表於2017-04-19

MySQL使用profile分析語句效能消耗



MySQL可以使用profile分析SQL語句的效能消耗情況。例如,查詢到SQL會執行多少時間,並看出CPU、記憶體使用量,執行過程中系統鎖及表鎖的花費時間等資訊。

透過have_profiling引數可以檢視MySQL是否支援profile,透過profiling引數可以檢視當前系統profile是否開啟:

檢視profile是否開啟:

mysql> show variables like '%profil%';

+------------------------+-------+

| Variable_name          | Value |

+------------------------+-------+

| have_profiling         | YES   |         --當前MySQL是否支援profile

| profiling              | OFF   |         --開啟SQL語句剖析功能

| profiling_history_size | 15    |         --設定保留profiling的數目,預設為15,範圍為0100,為0時將禁用profiling

+------------------------+-------+

以下是有關profile的一些常用命令:

set profiling = 1;  #基於會話級別開啟,關閉則用set profiling = off

show profile for query 1; #1query_id

show profile cpu for query 1;  #檢視CPU的消耗情況

show profile memory for query 1;  #檢視記憶體消耗情況

show profile block io,cpu for query 1;  #檢視I/OCPU的消耗情況

命令“show profile for query”的結果中有Sending data,該狀態表示MySQL執行緒開始訪問資料行並把結果返回給客戶端,而不僅僅是返回結果給客戶端。由於在Sending data狀態下,MySQL執行緒往往需要做大量的磁碟讀取操作,所以經常是整個查詢中耗時最長的狀態。

可以使用如下的語句查詢SQL的整體消耗百分比:

SELECT STATE,

       SUM(DURATION) AS TOTAL_R,

       ROUND(100 * SUM(DURATION) / (SELECT SUM(DURATION) FROM INFORMATION_SCHEMA.PROFILING  WHERE QUERY_ID = 1),2) AS PCT_R,

       COUNT(*) AS CALLS,

       SUM(DURATION) / COUNT(*) AS "R/Call"

  FROM INFORMATION_SCHEMA.PROFILING

 WHERE QUERY_ID = 1

 GROUP BY STATE

 ORDER BY TOTAL_R DESC;

profile是一個非常量化的指標,可以根據這些量化指標來比較各項資源的消耗,有利於對SQL語句的整體把控。在獲取到最消耗時間的執行緒狀態後,MySQL支援進一步選擇allcpublock iocontext switchpage faults等明細型別來檢視MySQL在使用什麼資源上耗費了過高的時間。

可以透過show profile source for query檢視SQL解析執行過程中每個步驟對應的原始碼的檔案、函式名以及具體的原始檔行數:

mysql>  show profile source for query 1;

+----------------+----------+-----------------------+--------------+-------------+

| Status         | Duration | Source_function       | Source_file  | Source_line |

+----------------+----------+-----------------------+--------------+-------------+

| starting       | 0.000118 | NULL                  | NULL         |        NULL |

| query end      | 0.000008 | mysql_execute_command | sql_parse.cc |        4967 |

| closing tables | 0.000004 | mysql_execute_command | sql_parse.cc |        5019 |

| freeing items  | 0.000010 | mysql_parse           | sql_parse.cc |        5593 |

| cleaning up    | 0.000012 | dispatch_command      | sql_parse.cc |        1902 |

+----------------+----------+-----------------------+--------------+-------------+

5 rows in set, 1 warning (0.01 sec)

show profile能夠在做SQL最佳化時幫助DBA瞭解時間都耗費到哪裡去了,從MySQL 5.6開始,可以透過trace檔案進一步獲取最佳化器時如何選擇執行計劃的。

使用示例如下所示:

mysql> SELECT @@profiling;

+-------------+

| @@profiling |

+-------------+

|           0 |

+-------------+

1 row in set (0.00 sec)

 

mysql> SET profiling = 1;

Query OK, 0 rows affected (0.00 sec)

 

mysql> DROP TABLE IF EXISTS t1;

Query OK, 0 rows affected, 1 warning (0.00 sec)

 

mysql> CREATE TABLE T1 (id INT);

Query OK, 0 rows affected (0.01 sec)

 

mysql> SHOW PROFILES;

+----------+----------+--------------------------+

| Query_ID | Duration | Query                    |

+----------+----------+--------------------------+

|        0 | 0.000088 | SET PROFILING = 1        |

|        1 | 0.000136 | DROP TABLE IF EXISTS t1  |

|        2 | 0.011947 | CREATE TABLE t1 (id INT) |

+----------+----------+--------------------------+

3 rows in set (0.00 sec)

 

mysql> SHOW PROFILE;

+----------------------+----------+

| Status               | Duration |

+----------------------+----------+

| checking permissions | 0.000040 |

| creating table       | 0.000056 |

| After create         | 0.011363 |

| query end            | 0.000375 |

| freeing items        | 0.000089 |

| logging slow query   | 0.000019 |

| cleaning up          | 0.000005 |

+----------------------+----------+

7 rows in set (0.00 sec)

 

mysql> SHOW PROFILE FOR QUERY 1;

+--------------------+----------+

| Status             | Duration |

+--------------------+----------+

| query end          | 0.000107 |

| freeing items      | 0.000008 |

| logging slow query | 0.000015 |

| cleaning up        | 0.000006 |

+--------------------+----------+

4 rows in set (0.00 sec)

 

mysql> SHOW PROFILE CPU FOR QUERY 2;

+----------------------+----------+----------+------------+

| Status               | Duration | CPU_user | CPU_system |

+----------------------+----------+----------+------------+

| checking permissions | 0.000040 | 0.000038 |   0.000002 |

| creating table       | 0.000056 | 0.000028 |   0.000028 |

| After create         | 0.011363 | 0.000217 |   0.001571 |

| query end            | 0.000375 | 0.000013 |   0.000028 |

| freeing items        | 0.000089 | 0.000010 |   0.000014 |

| logging slow query   | 0.000019 | 0.000009 |   0.000010 |

| cleaning up          | 0.000005 | 0.000003 |   0.000002 |

+----------------------+----------+----------+------------+

需要注意的是,INFORMATION_SCHEMA.PROFILINGSHOW PROFILESMySQL 5.7.2中已經標記為廢除,警告資訊為:

'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead

'INFORMATION_SCHEMA.PROFILING' is deprecated and will be removed in a future release. Please use Performance Schema instead

官網請參考:https://dev.mysql.com/doc/refman/5.7/en/performance-schema-query-profiling.html

 

& 說明:

有關profile的更多內容可以參考我的部落格:http://blog.itpub.net/26736162/viewspace-2135700/

 





https://dev.mysql.com/doc/refman/5.7/en/performance-schema-query-profiling.html
mysql> ? SHOW PROFILES
Name: 'SHOW PROFILES'
Description:
Syntax:
SHOW PROFILES


The SHOW PROFILES statement, together with SHOW PROFILE, displays
profiling information that indicates resource usage for statements
executed during the course of the current session. For more
information, see [HELP SHOW PROFILE].


*Note*:


These statements are deprecated and will be removed in a future MySQL
release. Use the Performance Schema instead; see
http://dev.mysql.com/doc/refman/5.7/en/performance-schema.html.


URL: http://dev.mysql.com/doc/refman/5.7/en/show-profiles.html

mysql> ? SHOW PROFILE
Name: 'SHOW PROFILE'
Description:
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


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 and will be removed in a future MySQL
release. Use the Performance Schema instead; see
http://dev.mysql.com/doc/refman/5.7/en/performance-schema-query-profili
ng.html.


Profiling is controlled by the profiling session variable, which has a
default value of 0 (OFF). Profiling is enabled by setting profiling to
1 or ON:


mysql> SET profiling = 1;


SHOW PROFILES displays a list of the most recent statements sent to the
server. The size of the list is controlled by the
profiling_history_size session variable, which has a default value of
15. The maximum value is 100. Setting the value to 0 has the practical
effect of disabling profiling.


All statements are profiled except SHOW PROFILE and SHOW PROFILES, so
you will find neither of those statements in the profile list.
Malformed statements are profiled. For example, SHOW PROFILING is an
illegal statement, and a syntax error occurs if you try to execute it,
but it will show up in the profiling list.


SHOW PROFILE displays detailed information about a single statement.
Without the FOR QUERY n clause, the output pertains to the most
recently executed statement. If FOR QUERY n is included, SHOW PROFILE
displays information for statement n. The values of n correspond to the
Query_ID values displayed by SHOW PROFILES.


The LIMIT row_count clause may be given to limit the output to
row_count rows. If LIMIT is given, OFFSET offset may be added to begin
the output offset rows into the full set of rows.


By default, SHOW PROFILE displays Status and Duration columns. The
Status values are like the State values displayed by SHOW PROCESSLIST,
although there might be some minor differences in interpretion for the
two statements for some status values (see
http://dev.mysql.com/doc/refman/5.7/en/thread-information.html).


Optional type values may be specified to display specific additional
types of information:


o ALL displays all information


o BLOCK IO displays counts for block input and output operations


o CONTEXT SWITCHES displays counts for voluntary and involuntary
  context switches


o CPU displays user and system CPU usage times


o IPC displays counts for messages sent and received


o MEMORY is not currently implemented


o PAGE FAULTS displays counts for major and minor page faults


o 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


o SWAPS displays swap counts


Profiling is enabled per session. When a session ends, its profiling
information is lost.


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


Examples:
mysql> SELECT @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set (0.00 sec)


mysql> SET profiling = 1;
Query OK, 0 rows affected (0.00 sec)


mysql> DROP TABLE IF EXISTS t1;
Query OK, 0 rows affected, 1 warning (0.00 sec)


mysql> CREATE TABLE T1 (id INT);
Query OK, 0 rows affected (0.01 sec)


mysql> SHOW PROFILES;
+----------+----------+--------------------------+
| Query_ID | Duration | Query                    |
+----------+----------+--------------------------+
|        0 | 0.000088 | SET PROFILING = 1        |
|        1 | 0.000136 | DROP TABLE IF EXISTS t1  |
|        2 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)


mysql> SHOW PROFILE;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table       | 0.000056 |
| After create         | 0.011363 |
| query end            | 0.000375 |
| freeing items        | 0.000089 |
| logging slow query   | 0.000019 |
| cleaning up          | 0.000005 |
+----------------------+----------+
7 rows in set (0.00 sec)


mysql> SHOW PROFILE FOR QUERY 1;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| query end          | 0.000107 |
| freeing items      | 0.000008 |
| logging slow query | 0.000015 |
| cleaning up        | 0.000006 |
+--------------------+----------+
4 rows in set (0.00 sec)


mysql> SHOW PROFILE CPU FOR QUERY 2;
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000038 |   0.000002 |
| creating table       | 0.000056 | 0.000028 |   0.000028 |
| After create         | 0.011363 | 0.000217 |   0.001571 |
| query end            | 0.000375 | 0.000013 |   0.000028 |
| freeing items        | 0.000089 | 0.000010 |   0.000014 |
| logging slow query   | 0.000019 | 0.000009 |   0.000010 |
| cleaning up          | 0.000005 | 0.000003 |   0.000002 |
+----------------------+----------+----------+------------+
7 rows in set (0.00 sec)








--檢視profile是否開啟
mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| profiling              | OFF   |         --開啟SQL語句剖析功能                                                  
| profiling_history_size | 15    |         --設定保留profiling的數目,預設為15,範圍為0至100,為0時將禁用profiling
+------------------------+-------+
2 rows in set (0.00 sec)

--基於會話級別開啟
mysql> set profiling = 1;          --關閉則用set profiling = off
Query OK, 0 rows affected (0.00 sec)
 
mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| profiling              | ON    |
| profiling_history_size | 15    |
+------------------------+-------+
2 rows in set (0.00 sec)

mysql>  select distinct d.account,a.server_id from tab_appserver_user a
    -> inner join tab_department_parent b on a.key_id = b.parent_id
    -> inner join tab_department_member c on b.department_id = c.department_id and c.state=1
    -> and c.isdefault=1  inner join tab_user_info d on c.user_id = d.user_id and d.state=1
    -> where a.type=1  
    -> union                   
    -> select distinct b.account,a.server_id from tab_appserver_user a
    -> inner join tab_user_info b on a.key_id = b.user_id and b.state=1
    -> where a.type=0;

--顯示快取的profile    
mysql> show profiles;
+----------+------------+-------------------------------------------------------+
| Query_ID | Duration   | Query
         1 | 0.86754250 | select distinct d.account,a.server_id from tab_appserver_user a
+----------+------------+-------------------------------------------------------+
4 rows in set (0.00 sec)
從上面可以看到時間的消耗為0.8秒

以下是具體的消耗,進行詳細的列出
mysql> show profile for query 1;       --1是query_id
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000018 |
| checking query cache for query | 0.000099 |
| Opening tables                 | 0.000963 |
| System lock                    | 0.000015 |
| Table lock                     | 0.000169 |
| optimizing                     | 0.000020 |
| statistics                     | 0.000027 |
| preparing                      | 0.000018 |
| Creating tmp table             | 0.000055 |
| executing                      | 0.000003 |
| Copying to tmp table           | 0.704845 |       --最主要的消耗點
| Sending data                   | 0.130039 |
| optimizing                     | 0.000029 |
| statistics                     | 0.000029 |
| preparing                      | 0.000020 |
| Creating tmp table             | 0.000142 |
| executing                      | 0.000003 |
| Copying to tmp table           | 0.000086 |
| Sending data                   | 0.000067 |
| optimizing                     | 0.000004 |
| statistics                     | 0.000005 |
| preparing                      | 0.000005 |
| executing                      | 0.000002 |
| Sending data                   | 0.023963 |
| removing tmp table             | 0.003420 |
| Sending data                   | 0.000005 |
| removing tmp table             | 0.003308 |
| Sending data                   | 0.000006 |
| removing tmp table             | 0.000007 |
| Sending data                   | 0.000009 |
| query end                      | 0.000003 |
| freeing items                  | 0.000144 |
| storing result in query cache  | 0.000011 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000006 |
+--------------------------------+----------+
35 rows in set (0.00 sec)

--檢視cpu的消耗情況    
mysql> show profile cpu for query 1;
+--------------------------------+----------+----------+------------+
| Status                         | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting                       | 0.000018 |     NULL |       NULL |
| checking query cache for query | 0.000099 |     NULL |       NULL |
| Opening tables                 | 0.000963 |     NULL |       NULL |
| System lock                    | 0.000015 |     NULL |       NULL |
| Table lock                     | 0.000169 |     NULL |       NULL |
| optimizing                     | 0.000020 |     NULL |       NULL |
| statistics                     | 0.000027 |     NULL |       NULL |
| preparing                      | 0.000018 |     NULL |       NULL |
| Creating tmp table             | 0.000055 |     NULL |       NULL |
| executing                      | 0.000003 |     NULL |       NULL |
| Copying to tmp table           | 0.704845 |     NULL |       NULL |  --此項消耗cpu最多
| Sending data                   | 0.130039 |     NULL |       NULL |
| optimizing                     | 0.000029 |     NULL |       NULL |
| statistics                     | 0.000029 |     NULL |       NULL |
| preparing                      | 0.000020 |     NULL |       NULL |
| Creating tmp table             | 0.000142 |     NULL |       NULL |
| executing                      | 0.000003 |     NULL |       NULL |
| Copying to tmp table           | 0.000086 |     NULL |       NULL |
| Sending data                   | 0.000067 |     NULL |       NULL |
| optimizing                     | 0.000004 |     NULL |       NULL |
| statistics                     | 0.000005 |     NULL |       NULL |
| preparing                      | 0.000005 |     NULL |       NULL |
| executing                      | 0.000002 |     NULL |       NULL |
| Sending data                   | 0.023963 |     NULL |       NULL |
| removing tmp table             | 0.003420 |     NULL |       NULL |
| Sending data                   | 0.000005 |     NULL |       NULL |
| removing tmp table             | 0.003308 |     NULL |       NULL |
| Sending data                   | 0.000006 |     NULL |       NULL |
| removing tmp table             | 0.000007 |     NULL |       NULL |
| Sending data                   | 0.000009 |     NULL |       NULL |
| query end                      | 0.000003 |     NULL |       NULL |
| freeing items                  | 0.000144 |     NULL |       NULL |
| storing result in query cache  | 0.000011 |     NULL |       NULL |
| logging slow query             | 0.000003 |     NULL |       NULL |
| cleaning up                    | 0.000006 |     NULL |       NULL |
+--------------------------------+----------+----------+------------+
35 rows in set (0.00 sec)

--檢視記憶體消耗
mysql> show profile memory for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000018 |
| checking query cache for query | 0.000099 |
| Opening tables                 | 0.000963 |
| System lock                    | 0.000015 |
| Table lock                     | 0.000169 |
| optimizing                     | 0.000020 |
| statistics                     | 0.000027 |
| preparing                      | 0.000018 |
| Creating tmp table             | 0.000055 |
| executing                      | 0.000003 |
| Copying to tmp table           | 0.704845 |
| Sending data                   | 0.130039 |
| optimizing                     | 0.000029 |
| statistics                     | 0.000029 |
| preparing                      | 0.000020 |
| Creating tmp table             | 0.000142 |
| executing                      | 0.000003 |
| Copying to tmp table           | 0.000086 |
| Sending data                   | 0.000067 |
| optimizing                     | 0.000004 |
| statistics                     | 0.000005 |
| preparing                      | 0.000005 |
| executing                      | 0.000002 |
| Sending data                   | 0.023963 |
| removing tmp table             | 0.003420 |
| Sending data                   | 0.000005 |
| removing tmp table             | 0.003308 |
| Sending data                   | 0.000006 |
| removing tmp table             | 0.000007 |
| Sending data                   | 0.000009 |
| query end                      | 0.000003 |
| freeing items                  | 0.000144 |
| storing result in query cache  | 0.000011 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000006 |
+--------------------------------+----------+

--檢視io及cpu的消耗
mysql> show profile block io,cpu for query 1;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000018 |     NULL |       NULL |         NULL |          NULL |
| checking query cache for query | 0.000099 |     NULL |       NULL |         NULL |          NULL |
| Opening tables                 | 0.000963 |     NULL |       NULL |         NULL |          NULL |
| System lock                    | 0.000015 |     NULL |       NULL |         NULL |          NULL |
| Table lock                     | 0.000169 |     NULL |       NULL |         NULL |          NULL |
| optimizing                     | 0.000020 |     NULL |       NULL |         NULL |          NULL |
| statistics                     | 0.000027 |     NULL |       NULL |         NULL |          NULL |
| preparing                      | 0.000018 |     NULL |       NULL |         NULL |          NULL |
| Creating tmp table             | 0.000055 |     NULL |       NULL |         NULL |          NULL |
| executing                      | 0.000003 |     NULL |       NULL |         NULL |          NULL |
| Copying to tmp table           | 0.704845 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.130039 |     NULL |       NULL |         NULL |          NULL |
| optimizing                     | 0.000029 |     NULL |       NULL |         NULL |          NULL |
| statistics                     | 0.000029 |     NULL |       NULL |         NULL |          NULL |
| preparing                      | 0.000020 |     NULL |       NULL |         NULL |          NULL |
| Creating tmp table             | 0.000142 |     NULL |       NULL |         NULL |          NULL |
| executing                      | 0.000003 |     NULL |       NULL |         NULL |          NULL |
| Copying to tmp table           | 0.000086 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.000067 |     NULL |       NULL |         NULL |          NULL |
| optimizing                     | 0.000004 |     NULL |       NULL |         NULL |          NULL |
| statistics                     | 0.000005 |     NULL |       NULL |         NULL |          NULL |
| preparing                      | 0.000005 |     NULL |       NULL |         NULL |          NULL |
| executing                      | 0.000002 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.023963 |     NULL |       NULL |         NULL |          NULL |
| removing tmp table             | 0.003420 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.000005 |     NULL |       NULL |         NULL |          NULL |
| removing tmp table             | 0.003308 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.000006 |     NULL |       NULL |         NULL |          NULL |
| removing tmp table             | 0.000007 |     NULL |       NULL |         NULL |          NULL |
| Sending data                   | 0.000009 |     NULL |       NULL |         NULL |          NULL |
| query end                      | 0.000003 |     NULL |       NULL |         NULL |          NULL |
| freeing items                  | 0.000144 |     NULL |       NULL |         NULL |          NULL |
| storing result in query cache  | 0.000011 |     NULL |       NULL |         NULL |          NULL |
| logging slow query             | 0.000003 |     NULL |       NULL |         NULL |          NULL |
| cleaning up                    | 0.000006 |     NULL |       NULL |         NULL |          NULL |
+--------------------------------+----------+----------+------------+--------------+---------------+
35 rows in set (0.00 sec)


--使用查詢語句對消耗進行排序

mysql> SELECT STATE,
    ->        SUM(DURATION) AS TOTAL_R,
    ->        ROUND(100 * SUM(DURATION) /
    ->              (SELECT SUM(DURATION)
    ->                 FROM INFORMATION_SCHEMA.PROFILING
    ->                WHERE QUERY_ID = 1),
    ->              2) AS PCT_R,
    ->        COUNT(*) AS CALLS,
    ->        SUM(DURATION) / COUNT(*) AS "R/Call"
    ->   FROM INFORMATION_SCHEMA.PROFILING
    ->  WHERE QUERY_ID = 1
    ->  GROUP BY STATE
    ->  ORDER BY TOTAL_R DESC;

+--------------------------------+----------+-------+-------+--------------+
| STATE                          | Total_R  | Pct_R | Calls | R/Call       |
+--------------------------------+----------+-------+-------+--------------+
| Copying to tmp table           | 0.704931 | 81.26 |     2 | 0.3524655000 |
| Sending data                   | 0.154089 | 17.76 |     6 | 0.0256815000 |
| removing tmp table             | 0.006735 |  0.78 |     3 | 0.0022450000 |
| Opening tables                 | 0.000963 |  0.11 |     1 | 0.0009630000 |
| Creating tmp table             | 0.000197 |  0.02 |     2 | 0.0000985000 |
| Table lock                     | 0.000169 |  0.02 |     1 | 0.0001690000 |
| freeing items                  | 0.000144 |  0.02 |     1 | 0.0001440000 |
| checking query cache for query | 0.000099 |  0.01 |     1 | 0.0000990000 |
| statistics                     | 0.000061 |  0.01 |     3 | 0.0000203333 |
| optimizing                     | 0.000053 |  0.01 |     3 | 0.0000176667 |
| preparing                      | 0.000043 |  0.00 |     3 | 0.0000143333 |
| starting                       | 0.000018 |  0.00 |     1 | 0.0000180000 |
| System lock                    | 0.000015 |  0.00 |     1 | 0.0000150000 |
| storing result in query cache  | 0.000011 |  0.00 |     1 | 0.0000110000 |
| executing                      | 0.000008 |  0.00 |     3 | 0.0000026667 |
| cleaning up                    | 0.000006 |  0.00 |     1 | 0.0000060000 |
| logging slow query             | 0.000003 |  0.00 |     1 | 0.0000030000 |
| query end                      | 0.000003 |  0.00 |     1 | 0.0000030000 |
+--------------------------------+----------+-------+-------+--------------+
18 rows in set (0.01 sec)


--最後說明:

    profile是一個非常量化的指標,可以根據這些量化指標來比較各項資源的消耗,有利於我們對該語句的整體把控!




mysql語句效能開銷檢測profiling詳解

之前我介紹過msyql查詢最佳化explain檢查命令的使用,explain主要是檢查sql語句的基本效能,sql是否優秀,但不能檢視具體的涉及硬體資源的開銷,今天要介紹的這個profiling工具可以更細節的檢視資源的開銷,比較詳細。

首先這款效能檢查工具是針對每個session生效的,session結束了就要重要發起查詢檢測。

預設是關閉的,需要手動開啟:

SET profiling = 1;

開啟之後,發往mysql伺服器的語句可以透過SHOW PROFILES顯示出來,預設顯示15條,最大設定為100,透過設定變數profiling_history_size實現,設定為0將會禁用profiling。

語法

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

關於type的定義英文也簡單:

  • ALL displays all information

  • BLOCK IO displays counts for block input and output operations

  • CONTEXT SWITCHES displays counts for voluntary and involuntary context switches

  • CPU displays user and system CPU usage times

  • IPC displays counts for messages sent and received

  • 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

使用示例

檢視有沒有啟用profiling

mysql> SELECT @@profiling;

+-------------+

| @@profiling |

+-------------+

| 0 |

+-------------+

1 row in set (0.00 sec)

開啟profiling

mysql> SET profiling = 1;

Query OK, 0 rows affected (0.00 sec)

執行要分析的SQL語句

mysql> DROP TABLE IF EXISTS t1;

Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> CREATE TABLE T1 (id INT);

Query OK, 0 rows affected (0.01 sec)

檢查所有抓取到的分析語句效能指標

mysql> SHOW PROFILES;

+----------+----------+--------------------------+

| Query_ID | Duration | Query |

+----------+----------+--------------------------+

| 0 | 0.000088 | SET PROFILING = 1 |

| 1 | 0.000136 | DROP TABLE IF EXISTS t1 |

| 2 | 0.011947 | CREATE TABLE t1 (id INT) |

+----------+----------+--------------------------+

3 rows in set (0.00 sec)

顯示單個分析語句效能指標,指最近執行次數最多的那一條

mysql> SHOW PROFILE;

+----------------------+----------+

| Status | Duration |

+----------------------+----------+

| checking permissions | 0.000040 |

| creating table | 0.000056 |

| After create | 0.011363 |

| query end | 0.000375 |

| freeing items | 0.000089 |

| logging slow query | 0.000019 |

| cleaning up | 0.000005 |

+----------------------+----------+

7 rows in set (0.00 sec)

具體檢視某條分析語句的效能

mysql> SHOW PROFILE FOR QUERY 1;

+--------------------+----------+

| Status | Duration |

+--------------------+----------+

| query end | 0.000107 |

| freeing items | 0.000008 |

| logging slow query | 0.000015 |

| cleaning up | 0.000006 |

+--------------------+----------+

4 rows in set (0.00 sec)

你也可以檢視CPU或者其他資源消耗資訊

mysql> SHOW PROFILE CPU FOR QUERY 2;

+----------------------+----------+----------+------------+

| Status | Duration | CPU_user | CPU_system |

+----------------------+----------+----------+------------+

| checking permissions | 0.000040 | 0.000038 | 0.000002 |

| creating table | 0.000056 | 0.000028 | 0.000028 |

| After create | 0.011363 | 0.000217 | 0.001571 |

| query end | 0.000375 | 0.000013 | 0.000028 |

| freeing items | 0.000089 | 0.000010 | 0.000014 |

| logging slow query | 0.000019 | 0.000009 | 0.000010 |

| cleaning up | 0.000005 | 0.000003 | 0.000002 |

+----------------------+----------+----------+------------+

7 rows in set (0.00 sec)

其他使用方式

也可以透過查表的方式檢視分析語句的效能,所有show能看到的都會記錄在INFORMATION_SCHEMA表中,比如:

SELECT STATE, FORMAT(DURATION, 6) AS DURATION FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = 2 ORDER BY SEQ;

SHOW與INFORMATION_SCHEMA對應關係表:

INFORMATION_SCHEMA Name SHOW Name Remarks
QUERY_ID Query_ID
SEQ

STATE Status
DURATION Duration
CPU_USER CPU_user
CPU_SYSTEM CPU_system
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

注意

INFORMATION_SCHEMA這個表的使用方式已經在mysql5.7.2已經標記廢除了,在未來的版本將會徹底刪除掉,SHOW的使用方式在未來的版本也會替代掉,替代使用方式為MySQL Performance Schema,具體的參考官網的使用:https://dev.mysql.com/doc/refman/5.7/en/performance-schema.html

以上profiling所有介紹翻譯來源於官網,原版可以參考:https://dev.mysql.com/doc/refman/5.7/en/show-profile.html






https://dev.mysql.com/doc/refman/5.7/en/show-profile.html

14.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

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 and will be removed in a future MySQL release. Use the Performance Schema instead; see Section 25.17.1, “Query Profiling Using Performance Schema”.

Profiling is controlled by the profiling session variable, which has a default value of 0 (OFF). Profiling is enabled by setting profiling to 1 or ON:

mysql> SET profiling = 1; 

SHOW PROFILES displays a list of the most recent statements sent to the server. The size of the list is controlled by the profiling_history_size session variable, which has a default value of 15. The maximum value is 100. Setting the value to 0 has the practical effect of disabling profiling.

All statements are profiled except SHOW PROFILE and SHOW PROFILES, so you will find neither of those statements in the profile list. Malformed statements are profiled. For example, SHOW PROFILING is an illegal statement, and a syntax error occurs if you try to execute it, but it will show up in the profiling list.

SHOW PROFILE displays detailed information about a single statement. Without the FOR QUERY n clause, the output pertains to the most recently executed statement. If FOR QUERY n is included, SHOW PROFILE displays information for statement n. The values of n correspond to the Query_ID values displayed by SHOW PROFILES.

The LIMIT row_count clause may be given to limit the output to row_count rows. If LIMIT is given, OFFSET offset may be added to begin the output offset rows into the full set of rows.

By default, SHOW PROFILE displays Status and Duration columns. The Status values are like the State values displayed by SHOW PROCESSLIST, although there might be some minor differences in interpretion for the two statements for some status values (see Section 9.14, “Examining Thread Information”).

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 operations

  • CONTEXT SWITCHES displays counts for voluntary and involuntary context switches

  • CPU displays user and system CPU usage times

  • IPC displays counts for messages sent and received

  • 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

Profiling is enabled per session. When a session ends, its profiling information is lost.

mysql> SELECT @@profiling; +-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set (0.00 sec)

mysql> SET profiling = 1; Query OK, 0 rows affected (0.00 sec)

mysql> DROP TABLE IF EXISTS t1; Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> CREATE TABLE T1 (id INT); Query OK, 0 rows affected (0.01 sec)

mysql> SHOW PROFILES; 
+----------+----------+--------------------------+
| Query_ID | Duration | Query                    |
+----------+----------+--------------------------+
|        0 | 0.000088 | SET PROFILING = 1        |
|        1 | 0.000136 | DROP TABLE IF EXISTS t1  |
|        2 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)

mysql> SHOW PROFILE; 
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| checking permissions | 0.000040 |
| creating table       | 0.000056 |
| After create         | 0.011363 |
| query end            | 0.000375 |
| freeing items        | 0.000089 |
| logging slow query   | 0.000019 |
| cleaning up          | 0.000005 |
+----------------------+----------+
7 rows in set (0.00 sec)

mysql> SHOW PROFILE FOR QUERY 1; 
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| query end          | 0.000107 |
| freeing items      | 0.000008 |
| logging slow query | 0.000015 |
| cleaning up        | 0.000006 |
+--------------------+----------+
4 rows in set (0.00 sec)

mysql> SHOW PROFILE CPU FOR QUERY 2;  
+----------------------+----------+----------+------------+
| Status               | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| checking permissions | 0.000040 | 0.000038 |   0.000002 |
| creating table       | 0.000056 | 0.000028 |   0.000028 |
| After create         | 0.011363 | 0.000217 |   0.001571 |
| query end            | 0.000375 | 0.000013 |   0.000028 |
| freeing items        | 0.000089 | 0.000010 |   0.000014 |
| logging slow query   | 0.000019 | 0.000009 |   0.000010 |
| cleaning up          | 0.000005 | 0.000003 |   0.000002 |
+----------------------+----------+----------+------------+
7 rows in set (0.00 sec)
Note

Profiling is only partially functional on some architectures. For values that depend on the getrusage() system call, NULL is returned on systems such as Windows that do not support the call. In addition, profiling is per process and not per thread. This means that activity on threads within the server other than your own may affect the timing information that you see.

You can also get profiling information from the PROFILING table in INFORMATION_SCHEMA. See Section 24.18, “The INFORMATION_SCHEMA PROFILING Table”. For example, the following queries produce the same result:

SHOW PROFILE FOR QUERY 2;

SELECT STATE, FORMAT(DURATION, 6) AS DURATION
FROM INFORMATION_SCHEMA.PROFILING
WHERE QUERY_ID = 2 ORDER BY SEQ;

24.18 The INFORMATION_SCHEMA PROFILING Table

The PROFILING table provides statement profiling information. Its contents correspond to the information produced by the SHOW PROFILES and SHOW PROFILE statements (see Section 14.7.5.31, “SHOW PROFILES Syntax”). The table is empty unless theprofiling session variable is set to 1.

Note

This table is deprecated as of MySQL 5.7.2 and will be removed in a future MySQL release. Use the Performance Schema instead; see Chapter 25, MySQL Performance Schema.

INFORMATION_SCHEMA Name SHOW Name Remarks
QUERY_ID Query_ID  
SEQ  
STATE Status  
DURATION Duration  
CPU_USER CPU_user  
CPU_SYSTEM CPU_system  
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  

Notes:

  • 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_FUNCTIONSOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.



About Me

...............................................................................................................................

● 本文整理自網路

● 本文在itpub(http://blog.itpub.net/26736162)、部落格園(http://www.cnblogs.com/lhrbest)和個人微信公眾號(xiaomaimiaolhr)上有同步更新

● 本文itpub地址:http://blog.itpub.net/26736162/abstract/1/

● 本文部落格園地址:http://www.cnblogs.com/lhrbest

● 本文pdf版及小麥苗雲盤地址:http://blog.itpub.net/26736162/viewspace-1624453/

● 資料庫筆試面試題庫及解答:http://blog.itpub.net/26736162/viewspace-2134706/

● QQ群:230161599     微信群:私聊

● 聯絡我請加QQ好友(646634621),註明新增緣由

● 於 2017-07-01 09:00 ~ 2017-07-31 22:00 在魔都完成

● 文章內容來源於小麥苗的學習筆記,部分整理自網路,若有侵權或不當之處還請諒解

● 版權所有,歡迎分享本文,轉載請保留出處

...............................................................................................................................

拿起手機使用微信客戶端掃描下邊的左邊圖片來關注小麥苗的微信公眾號:xiaomaimiaolhr,掃描右邊的二維碼加入小麥苗的QQ群,學習最實用的資料庫技術。

MySQL使用profile分析語句效能消耗
DBA筆試面試講解
歡迎與我聯絡

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/29734436/viewspace-2137628/,如需轉載,請註明出處,否則將追究法律責任。

相關文章