在日常的工作中，我们通常要分析SQL语句的性能，通过会使用到执行计划，利用执行计划来分析SQL语句的性能，并进行相应的优化；本文将利用profile分析SQL语句的执行过程来辅助的分析SQL语句，做好优化；
分析SQL执行带来的开销是优化SQL的重要手段。在MySQL数据库中，可以通过配置profiling参数来启用SQL剖析。该参数可以在全局和session级别来设置。对于全局级别则作用于整个MySQL实例，而session级别紧影响当前session。该参数开启后，后续执行的SQL语句都将记录其资源开销，诸如IO，上下文切换，CPU，Memory等等。根据这些开销进一步分析当前SQL瓶颈从而进行优化与调整。本文描述了如何使用MySQL profile以及利用Performance_Schema来查询profile的SQL执行过程的样例；
一、有关profile的描述
1、查看profiling系统变量
root@localhost [wjq]>show variables like '%profil%'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | have_profiling | YES | | profiling | OFF | | profiling_history_size | 15 | +------------------------+-------+ 3 rows in set (0.00 sec)
参数说明：
have_profiling:只读变量，用于控制是否有系统变量开启或关闭profiling
profiling：开启或关系SQL语句剖析功能
profiling_history_size：设置保留profiling的数据，默认是15，范围为0~100，0表示将禁用profiling
2、获取profiling的帮助信息
root@localhost [wjq]>help profile
Name: 'SHOW PROFILE'
Description:
Syntax:
SHOW PROFILE [type [, type] ... ]
[FOR QUERY n]
[LIMIT row_count [OFFSET offset]]
type:
ALL #显示所有的开销信息
| BLOCK IO #显示块IO的开销信息
| CONTEXT SWITCHES #上下文切换开销信息
| CPU #显示CPU相关开销信息
| IPC #显示发送和接受相关开销信息
| MEMORY #显示内存相关开销信息
| PAGE FAULTS #显示页面错误相关开销信息
| SOURCE #显示和source_funcation、source_file、source_line相关的开销信息
| 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.
3、开启porfiling
启用session级别的profiling
root@localhost [wjq]>SET profiling = 1; Query OK, 0 rows affected, 1 warning (0.00 sec) root@localhost [wjq]>show variables like '%profil%'; +------------------------+-------+ | Variable_name | Value | +------------------------+-------+ | have_profiling | YES | | profiling | ON | | profiling_history_size | 15 | +------------------------+-------+ 3 rows in set (0.01 sec)
4、执行SQL查询
root@localhost [wjq]>select count(*) from wjq_innodb_count2; +----------+ | count(*) | +----------+ | 4 | +----------+ 1 row in set (0.00 sec) root@localhost [wjq]>select count(*) from wjq_innodb_count1; +----------+ | count(*) | +----------+ | 100001 | +----------+ 1 row in set (0.04 sec)
5、查看当前session所有已产生的profile
root@localhost [wjq]>show profiles; +----------+------------+----------------------------------------+ | Query_ID | Duration | Query | +----------+------------+----------------------------------------+ | 1 | 0.00156350 | show variables like '%profil%' | | 2 | 0.00023575 | select count(*) from wjq_innodb_count2 | | 3 | 0.03346325 | select count(*) from wjq_innodb_count1 | +----------+------------+----------------------------------------+ 3 rows in set, 1 warning (0.00 sec)
发现有一个告警信息
root@localhost [wjq]>show warnings\G; *************************** 1. row *************************** Level: Warning Code: 1287 Message: 'SHOW PROFILES' is deprecated and will be removed in a future release. Please use Performance Schema instead 1 row in set (0.00 sec)
告警是说SHOW PROFILES命令将来会被Performance_Schema替换掉。关于利用Performance_Schema来查询profile将在文章第二部分进行介绍；
6、获取SQL语句的开销信息
开启profiling后，我们可以通过show profile等方式查看，其实这些开销信息被记录到information_schema.profiling表中。注show profile之类的语句不会被profiling，即自身不会产生Profiling。
我们下面的这个show profile查看的是show warnings产生的相应开销。
root@localhost [wjq]>show profile; +----------------+----------+ | Status | Duration | +----------------+----------+ | starting | 0.000051 | | query end | 0.000005 | | closing tables | 0.000006 | | freeing items | 0.000009 | | cleaning up | 0.000012 | +----------------+----------+ 5 rows in set, 1 warning (0.00 sec)
7、获取指定查询的开销（Druation表示持续时间）
root@localhost [wjq]>show profile for query 3; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000067 | | checking permissions | 0.000007 | | Opening tables | 0.000017 | | init | 0.000013 | | System lock | 0.000008 | | optimizing | 0.000004 | | statistics | 0.000013 | | preparing | 0.000011 | | executing | 0.000003 | | Sending data | 0.033256 | | end | 0.000010 | | query end | 0.000011 | | closing tables | 0.000013 | | freeing items | 0.000018 | | cleaning up | 0.000014 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec)
输入说明
Sending data：这个状态的名称很具有误导性，所谓的“Sending data”并不是单纯的发送数据，而是包括“收集 + 发送 数据”。
query end：表示语句执行完毕了，但是还有一些后续工作没做完时的状态。
freeing items：释放查询缓存里面的空间，如果是DML操作，所以相应的缓存里的记录就无效了，所以需要有这一步做处理。
查看所有开销
查看特定部分的开销，如下为CPU部分的开销
root@localhost [wjq]>show profile cpu for query 3; +----------------------+----------+----------+------------+ | Status | Duration | CPU_user | CPU_system | +----------------------+----------+----------+------------+ | starting | 0.000067 | 0.000063 | 0.000000 | | checking permissions | 0.000007 | 0.000006 | 0.000000 | | Opening tables | 0.000017 | 0.000017 | 0.000000 | | init | 0.000013 | 0.000013 | 0.000000 | | System lock | 0.000008 | 0.000008 | 0.000000 | | optimizing | 0.000004 | 0.000004 | 0.000000 | | statistics | 0.000013 | 0.000014 | 0.000000 | | preparing | 0.000011 | 0.000011 | 0.000000 | | executing | 0.000003 | 0.000003 | 0.000000 | | Sending data | 0.033256 | 0.033227 | 0.000000 | | end | 0.000010 | 0.000007 | 0.000000 | | query end | 0.000011 | 0.000010 | 0.000000 | | closing tables | 0.000013 | 0.000013 | 0.000000 | | freeing items | 0.000018 | 0.000018 | 0.000000 | | cleaning up | 0.000014 | 0.000014 | 0.000000 | +----------------------+----------+----------+------------+ 15 rows in set, 1 warning (0.00 sec)
查看MEMORY部分的开销
root@localhost [wjq]>show profile memory for query 3; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000067 | | checking permissions | 0.000007 | | Opening tables | 0.000017 | | init | 0.000013 | | System lock | 0.000008 | | optimizing | 0.000004 | | statistics | 0.000013 | | preparing | 0.000011 | | executing | 0.000003 | | Sending data | 0.033256 | | end | 0.000010 | | query end | 0.000011 | | closing tables | 0.000013 | | freeing items | 0.000018 | | cleaning up | 0.000014 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec)
同时查看不同资源开销
root@localhost [wjq]>show profile block io,cpu,memory for query 3; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000067 | 0.000063 | 0.000000 | 0 | 0 | | checking permissions | 0.000007 | 0.000006 | 0.000000 | 0 | 0 | | Opening tables | 0.000017 | 0.000017 | 0.000000 | 0 | 0 | | init | 0.000013 | 0.000013 | 0.000000 | 0 | 0 | | System lock | 0.000008 | 0.000008 | 0.000000 | 0 | 0 | | optimizing | 0.000004 | 0.000004 | 0.000000 | 0 | 0 | | statistics | 0.000013 | 0.000014 | 0.000000 | 0 | 0 | | preparing | 0.000011 | 0.000011 | 0.000000 | 0 | 0 | | executing | 0.000003 | 0.000003 | 0.000000 | 0 | 0 | | Sending data | 0.033256 | 0.033227 | 0.000000 | 0 | 0 | | end | 0.000010 | 0.000007 | 0.000000 | 0 | 0 | | query end | 0.000011 | 0.000010 | 0.000000 | 0 | 0 | | closing tables | 0.000013 | 0.000013 | 0.000000 | 0 | 0 | | freeing items | 0.000018 | 0.000018 | 0.000000 | 0 | 0 | | cleaning up | 0.000014 | 0.000014 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 15 rows in set, 1 warning (0.00 sec)
8、INFORMATION_SCHEMA.PROFILING
上面已经看到了，show profile命令即将移除，所以可以直接去information_schema.profiling表查看，灵活度更大，其表结构信息如下：
root@localhost [information_schema]>desc profiling; +---------------------+--------------+------+-----+----------+-------+ | Field | Type | Null | Key | Default | Extra | +---------------------+--------------+------+-----+----------+-------+ | QUERY_ID | int(20) | NO | | 0 | | | SEQ | int(20) | NO | | 0 | | | STATE | varchar(30) | NO | | | | | DURATION | decimal(9,6) | NO | | 0.000000 | | | CPU_USER | decimal(9,6) | YES | | NULL | | | CPU_SYSTEM | decimal(9,6) | YES | | NULL | | | CONTEXT_VOLUNTARY | int(20) | YES | | NULL | | | CONTEXT_INVOLUNTARY | int(20) | YES | | NULL | | | BLOCK_OPS_IN | int(20) | YES | | NULL | | | BLOCK_OPS_OUT | int(20) | YES | | NULL | | | MESSAGES_SENT | int(20) | YES | | NULL | | | MESSAGES_RECEIVED | int(20) | YES | | NULL | | | PAGE_FAULTS_MAJOR | int(20) | YES | | NULL | | | PAGE_FAULTS_MINOR | int(20) | YES | | NULL | | | SWAPS | int(20) | YES | | NULL | | | SOURCE_FUNCTION | varchar(30) | YES | | NULL | | | SOURCE_FILE | varchar(20) | YES | | NULL | | | SOURCE_LINE | int(20) | YES | | NULL | | +---------------------+--------------+------+-----+----------+-------+ 18 rows in set (0.00 sec)
下面的SQL语句用于查询query_id为3的SQL开销，且按最大耗用时间倒序排列
root@localhost [information_schema]>set @query_id=3;
Query OK, 0 rows affected (0.00 sec)
root@localhost [information_schema]>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(*) AS Calls,
-> SUM(DURATION) / COUNT(*) AS "R/Call"
-> FROM INFORMATION_SCHEMA.PROFILING
-> WHERE QUERY_ID = @query_id
-> GROUP BY STATE
-> ORDER BY Total_R DESC;
+----------------------+----------+-------+-------+--------------+
| STATE | Total_R | Pct_R | Calls | R/Call |
+----------------------+----------+-------+-------+--------------+
| Sending data | 0.033256 | 99.38 | 1 | 0.0332560000 |
| starting | 0.000067 | 0.20 | 1 | 0.0000670000 |
| freeing items | 0.000018 | 0.05 | 1 | 0.0000180000 |
| Opening tables | 0.000017 | 0.05 | 1 | 0.0000170000 |
| cleaning up | 0.000014 | 0.04 | 1 | 0.0000140000 |
| statistics | 0.000013 | 0.04 | 1 | 0.0000130000 |
| init | 0.000013 | 0.04 | 1 | 0.0000130000 |
| closing tables | 0.000013 | 0.04 | 1 | 0.0000130000 |
| query end | 0.000011 | 0.03 | 1 | 0.0000110000 |
| preparing | 0.000011 | 0.03 | 1 | 0.0000110000 |
| end | 0.000010 | 0.03 | 1 | 0.0000100000 |
| System lock | 0.000008 | 0.02 | 1 | 0.0000080000 |
| checking permissions | 0.000007 | 0.02 | 1 | 0.0000070000 |
| optimizing | 0.000004 | 0.01 | 1 | 0.0000040000 |
| executing | 0.000003 | 0.01 | 1 | 0.0000030000 |
+----------------------+----------+-------+-------+--------------+
15 rows in set, 16 warnings (0.01 sec)
停止profile,可以设置profiling参数，或者在session退出之后,profiling会被自动关闭。
关于show profile的使用详细可参考：https://dev.mysql.com/doc/refman/5.7/en/show-profile.html
二、利用Performance_Schema来查询profile
第一部分中介绍了，输出show profiles会有一个告警信息；告警信息内容已经过期即将在未来版本中删除，那么我们来看看新版本中推荐的performace_schema如何使用。先切换到performance_schema下，这是MySQL新增的性能优化引擎，在5.6以前是关闭的，5.6, 5.7中是默认开启的，5.7切换的时候还会有一句提示：
root@localhost [(none)]>use performance_schema; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A
提示我们在连接 MySQL 的时候可以使用-A 参数预读数据库。
使用profile涉及几个表，setup_actors、setup_instruments、setup_consumers。默认表setup_actors的内容如下：
root@localhost [performance_schema]>select * from setup_actors; +------+------+------+---------+---------+ | HOST | USER | ROLE | ENABLED | HISTORY | +------+------+------+---------+---------+ | % | % | % | YES | YES | +------+------+------+---------+---------+ 1 row in set (0.00 sec)
按照官方的建议，默认是启用，可以根据需求禁用。
root@localhost [performance_schema]>update performance_schema.setup_actors set enabled='no',history='no' where user='%' and host='%'; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0
禁用后的结果如下：
root@localhost [performance_schema]>select * from setup_actors; +------+------+------+---------+---------+ | HOST | USER | ROLE | ENABLED | HISTORY | +------+------+------+---------+---------+ | % | % | % | NO | NO | +------+------+------+---------+---------+ 1 row in set (0.00 sec)
然后加入指定的用户
root@localhost [performance_schema]>insert into performance_schema.setup_actors values('localhost','root','%','YES','YES');
Query OK, 1 row affected (0.00 sec)
root@localhost [performance_schema]>select * from setup_actors;
+-----------+------+------+---------+---------+
| HOST | USER | ROLE | ENABLED | HISTORY |
+-----------+------+------+---------+---------+
| % | % | % | NO | NO |
| localhost | root | % | YES | YES |
+-----------+------+------+---------+---------+
2 rows in set (0.00 sec)
好了，setup_actors 的配置就这样，另外两个表的内容修改也是大同小异。
表 setup_consumers 描述各种事件，
表setup_instruments 描述这个数据库下的表名以及是否开启监控。
我统计了一下，两个表的默认数据还不少。
setup_instruments 1028 rows
setup_consumers 15 rows
下面我们按照官方的建议来修改，可以看到修改的不是一行，而是相关的很多行。
root@localhost [performance_schema]>UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES'
-> WHERE NAME LIKE '%statement/%';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 193 Changed: 0 Warnings: 0
root@localhost [performance_schema]>UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES'
-> WHERE NAME LIKE '%stage/%';
Query OK, 123 rows affected (0.00 sec)
Rows matched: 132 Changed: 123 Warnings: 0
root@localhost [performance_schema]>UPDATE performance_schema.setup_consumers SET ENABLED = 'YES'
-> WHERE NAME LIKE '%events_statements_%';
Query OK, 1 row affected (0.00 sec)
Rows matched: 3 Changed: 1 Warnings: 0
root@localhost [performance_schema]>UPDATE performance_schema.setup_consumers SET ENABLED = 'YES'
-> WHERE NAME LIKE '%events_stages_%';
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3 Changed: 3 Warnings: 0
OK，配置完成；
下面我们来看一下具体要怎么用：
1、切换到wjq数据库
root@localhost [performance_schema]>use wjq; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed root@localhost [wjq]>
2、创建一个测试表test_profile，插入几行数据
root@localhost [wjq]>create table test_profile as select * from information_schema.columns limit 1,5; ERROR 1786 (HY000): Statement violates GTID consistency: CREATE TABLE ... SELECT. root@localhost [wjq]>create table test_profile like information_schema.columns; Query OK, 0 rows affected (0.00 sec) root@localhost [wjq]>insert into test_profile select * from information_schema.columns limit 1,5; Query OK, 5 rows affected (0.06 sec) Records: 5 Duplicates: 0 Warnings: 0
3、运行语句来得到一些详细的统计信息。
root@localhost [wjq]>select * from test.test_profile limit 1,2 \G
ERROR 1146 (42S02): Table 'test.test_profile' doesn't exist
root@localhost [wjq]>
root@localhost [wjq]>select * from test_profile limit 1,2 \G;
*************************** 1. row ***************************
TABLE_CATALOG: def
TABLE_SCHEMA: information_schema
TABLE_NAME: CHARACTER_SETS
COLUMN_NAME: DESCRIPTION
ORDINAL_POSITION: 3
COLUMN_DEFAULT:
IS_NULLABLE: NO
DATA_TYPE: varchar
CHARACTER_MAXIMUM_LENGTH: 60
CHARACTER_OCTET_LENGTH: 180
NUMERIC_PRECISION: NULL
NUMERIC_SCALE: NULL
DATETIME_PRECISION: NULL
CHARACTER_SET_NAME: utf8
COLLATION_NAME: utf8_general_ci
COLUMN_TYPE: varchar(60)
COLUMN_KEY:
EXTRA:
PRIVILEGES: select
COLUMN_COMMENT:
GENERATION_EXPRESSION:
*************************** 2. row ***************************
TABLE_CATALOG: def
TABLE_SCHEMA: information_schema
TABLE_NAME: CHARACTER_SETS
COLUMN_NAME: MAXLEN
ORDINAL_POSITION: 4
COLUMN_DEFAULT: 0
IS_NULLABLE: NO
DATA_TYPE: bigint
CHARACTER_MAXIMUM_LENGTH: NULL
CHARACTER_OCTET_LENGTH: NULL
NUMERIC_PRECISION: 19
NUMERIC_SCALE: 0
DATETIME_PRECISION: NULL
CHARACTER_SET_NAME: NULL
COLLATION_NAME: NULL
COLUMN_TYPE: bigint(3)
COLUMN_KEY:
EXTRA:
PRIVILEGES: select
COLUMN_COMMENT:
GENERATION_EXPRESSION:
2 rows in set (0.00 sec)
4、根据下面的语句查询一个历史表，从表名可以看出是和事件相关的，感觉越来越像Oracle了
root@localhost [wjq]>SELECT EVENT_ID, TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT
-> FROM performance_schema.events_statements_history_long
-> WHERE SQL_TEXT like '%limit 1,2%';
+----------+----------+-------------------------------------------+
| EVENT_ID | Duration | SQL_TEXT |
+----------+----------+-------------------------------------------+
| 13818 | 0.000174 | select * from test.test_profile limit 1,2 |
| 13826 | 0.000324 | select * from test_profile limit 1,2 |
+----------+----------+-------------------------------------------+
2 rows in set (0.00 sec)
我们通过上面的语句可以得到一个概览，对应的事件和执行时间。然后到stage相关的历史表中查看事件的详细信息，这就是我们期望的性能数据。如此一来应该就明白上面的配置表中所要做的工作是什么意思了。
root@localhost [wjq]>SELECT event_name AS Stage, TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration
-> FROM performance_schema.events_stages_history_long
-> WHERE NESTING_EVENT_ID=13826;
+--------------------------------+----------+
| Stage | Duration |
+--------------------------------+----------+
| stage/sql/starting | 0.000079 |
| stage/sql/checking permissions | 0.000007 |
| stage/sql/Opening tables | 0.000020 |
| stage/sql/init | 0.000039 |
| stage/sql/System lock | 0.000009 |
| stage/sql/optimizing | 0.000002 |
| stage/sql/statistics | 0.000017 |
| stage/sql/preparing | 0.000012 |
| stage/sql/executing | 0.000000 |
| stage/sql/Sending data | 0.000094 |
| stage/sql/end | 0.000001 |
| stage/sql/query end | 0.000010 |
| stage/sql/closing tables | 0.000009 |
| stage/sql/freeing items | 0.000013 |
| stage/sql/cleaning up | 0.000001 |
+--------------------------------+----------+
15 rows in set (0.00 sec)
整体来看，看到这个特性的输出，十分类似于Oracle中的Datapump，输出实在是太像了，很有条理。
关于使用performance_schema查看profile的信息详细可参考：https://dev.mysql.com/doc/refman/5.7/en/show-profile.html
如果您觉得本站对你有帮助，那么可以收藏和推荐本站，帮助本站更好地发展，在此谢过各位网友的支持。
转载请注明原文链接：MySQL有效利用profile分析SQL语句的执行过程
转载请注明原文链接：MySQL有效利用profile分析SQL语句的执行过程
