MySQL使用profile分析语句性能消耗
MySQL使用profile分析语句性能消耗
--查看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是一个非常量化的指标，可以根据这些量化指标来比较各项资源的消耗，有利于我们对该语句的整体把控！
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 |
| INFORMATION_SCHEMA Name | SHOW Name | Remarks |
|---|
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_FUNCTION, SOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.
About Me
...............................................................................................................................
● 本文转载自http://blog.itpub.net/29371470/viewspace-1355948/及MySQL官方文档
● 本文在itpub（http://blog.itpub.net/26736162）、博客园（http://www.cnblogs.com/lhrbest）和个人微信公众号（xiaomaimiaolhr）上有同步更新
● 本文pdf版及小麦苗云盘地址：http://blog.itpub.net/26736162/viewspace-1624453/
● QQ群：230161599 微信群：私聊
● 联系我请加QQ好友(642808185)，注明添加缘由
● 文章内容来源于小麦苗的学习笔记，部分整理自网络，若有侵权或不当之处还请谅解
● 版权所有，欢迎分享本文，转载请保留出处
...............................................................................................................................
拿起手机使用微信客户端扫描下边的左边图片来关注小麦苗的微信公众号：xiaomaimiaolhr，扫描右边的二维码加入小麦苗的QQ群，学习最实用的数据库技术。
--查看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是一个非常量化的指标，可以根据这些量化指标来比较各项资源的消耗，有利于我们对该语句的整体把控！
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 |
| INFORMATION_SCHEMA Name | SHOW Name | Remarks |
|---|
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_FUNCTION, SOURCE_FILE, and SOURCE_LINE provide information indicating where in the source code the profiled state executes.
正文到此结束
- 本文标签： rmi CDN sql key schema ACE 图片 云 https apr Select Sending data Word cache mysql ip cat HTML show processlist 博客 ORM mail 数据库 App QQ群 http message db find 时间 同步 DDL 微信公众号 windows swap IDE 二维码 src Logging id tab tar 数据 list dist 文章 IO ssl map value example Architect NIO
- 版权声明： 本文为互联网转载文章，出处已在文章中说明(部分除外)。如果侵权，请联系本站长删除，谢谢。
- 本文海报： 生成海报一 生成海报二
热门推荐
相关文章
近期评论
-
文章和留言都翻到11页了 没有OOM
-
-
朋友，翻页到11页，及以后，会出现OOM，无法访问
-
-
搞个gitee的项目
-
-
版本号是多少，你可以下载哪个代码仓库，jdk选1.8 直接跑就行
-
-
-
Loading...
![[HBLOG]公众号](https://www.liuhaihua.cn/img/qrcode_gzh.jpg)
