一、解释
SHOW PROFILE 和 SHOW PROFILES 语句显示分析信息,这些信息指示在当前会话过程中执行的语句的资源使用情况。
首先说明,show profile和show profiles是不一样的输出,但是又是有很大的联系,具体我们分开学习。
二、操作学习
1.show profiles
1.1 参数
mysql> show variables like "profil%";
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
2 rows in set (0.01 sec)
1.profiling
要使用此功能,需要打开该参数,该参数是会话级别参数并且默认值为 0 (OFF)。通过将 profiling 设置为 1 或 ON 来启用分析
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql>
2.profiling_history_size
该参数控制列表的大小,默认是15,最大是100
mysql> set profiling_history_size=100;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql>
1.2 举例
mysql> show profiles;
+----------+------------+----------------------------------+
| Query_ID | Duration | Query |
+----------+------------+----------------------------------+
| 8 | 0.00217825 | show variables like "profil%" |
| 9 | 0.00022925 | set profiling_history_size=15 |
| 10 | 0.00036525 | set profiling=1 |
| 11 | 0.00561450 | show variables like "profil%" |
| 12 | 0.00015300 | set frofiling=0 |
| 13 | 0.00039275 | create table t1(geng int) |
| 14 | 0.00022000 | SELECT DATABASE() |
| 15 | 0.00010825 | insert into t1 (geng) value 1 |
| 16 | 0.00010275 | insert into t1 (geng) values 1 |
| 17 | 0.00327375 | insert into t1 (geng) values (1) |
+----------+------------+----------------------------------+
10 rows in set, 1 warning (0.00 sec)
mysql>
2.show profile
2.1 格式
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
}
2.2 解释
除 SHOW PROFILE 和 SHOW PROFILES 之外的所有语句都进行了概要分析,因此这些语句均未出现在概要文件列表中。畸形的陈述被剖析。例如,SHOW PROFILING 是一个非法语句,如果您尝试执行它会出现语法错误,但它会显示在分析列表中。
SHOW PROFILE 显示有关单个语句的详细信息。如果没有 FOR QUERY n 子句,则输出与最近执行的语句有关。如果包含 FOR QUERY N,则 SHOW PROFILE 显示语句N 的信息。 N 的值对应于 SHOW PROFILES 显示的 Query_ID 值。
可以给出 LIMIT row_count 子句以将输出限制为 row_count 行。如果给出 LIMIT,则可以添加 OFFSET 偏移量以将输出偏移行开始到完整的行集。
2.3 类型
另外,看格式上有type,我们就来看看它的八大类型。
-
ALL 显示所有信息
-
BLOCK IO 显示块输入和输出操作的计数
-
CONTEXT SWITCHES 显示自愿和非自愿上下文切换的计数
-
CPU 显示用户和系统 CPU 使用时间
-
IPC 显示发送和接收消息的计数
-
MEMORY 目前未实现
-
PAGE FAULTS 显示主要和次要页面错误的计数
-
SOURCE 显示源代码中函数的名称,以及函数所在文件的名称和行号
-
SWAPS 显示交换计数
2.4 举例
前提:为了更好体现出效果,压测一些数据进行测试。
SHOW PROFILE
mysql> show profiles;
+----------+------------+-----------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------+
| 1 | 0.27360225 | select * from sbtest1 |
+----------+------------+-----------------------+
1 row in set, 1 warning (0.00 sec)
ALL
mysql> show profile ALL for query 1;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting | 0.000232 | 0.000161 | 0.000046 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| checking permissions | 0.000031 | 0.000022 | 0.000007 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 802 |
| Opening tables | 0.000055 | 0.000042 | 0.000012 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5709 |
| init | 0.000047 | 0.000037 | 0.000010 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 121 |
| System lock | 0.000027 | 0.000020 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 323 |
| optimizing | 0.000013 | 0.000011 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 151 |
| statistics | 0.000035 | 0.000029 | 0.000008 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 367 |
| preparing | 0.000038 | 0.000029 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 475 |
| executing | 0.000018 | 0.000013 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 119 |
| Sending data | 0.272893 | 0.222936 | 0.018862 | 39 | 4 | 0 | 0 | 0 | 0 | 0 | 2 | 0 | exec | sql_executor.cc | 195 |
| end | 0.000061 | 0.000034 | 0.000010 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 199 |
| query end | 0.000029 | 0.000022 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4946 |
| closing tables | 0.000028 | 0.000022 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 4998 |
| freeing items | 0.000035 | 0.000027 | 0.000008 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 5610 |
| cleaning up | 0.000061 | 0.000048 | 0.000014 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1924 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
15 rows in set, 1 warning (0.00 sec)
mysql>
BLOCK IO & LIMIT
mysql> show profile BLOCK IO for query 1 LIMIT 2;
+----------------------+----------+--------------+---------------+
| Status | Duration | Block_ops_in | Block_ops_out |
+----------------------+----------+--------------+---------------+
| starting | 0.000232 | 0 | 0 |
| checking permissions | 0.000031 | 0 | 0 |
+----------------------+----------+--------------+---------------+
2 rows in set, 1 warning (0.01 sec)
mysql>
CPU
mysql> show profile CPU for query 1;
+----------------------+----------+----------+------------+
| Status | Duration | CPU_user | CPU_system |
+----------------------+----------+----------+------------+
| starting | 0.000232 | 0.000161 | 0.000046 |
| checking permissions | 0.000031 | 0.000022 | 0.000007 |
| Opening tables | 0.000055 | 0.000042 | 0.000012 |
| init | 0.000047 | 0.000037 | 0.000010 |
| System lock | 0.000027 | 0.000020 | 0.000006 |
| optimizing | 0.000013 | 0.000011 | 0.000003 |
| statistics | 0.000035 | 0.000029 | 0.000008 |
| preparing | 0.000038 | 0.000029 | 0.000009 |
| executing | 0.000018 | 0.000013 | 0.000003 |
| Sending data | 0.272893 | 0.222936 | 0.018862 |
| end | 0.000061 | 0.000034 | 0.000010 |
| query end | 0.000029 | 0.000022 | 0.000006 |
| closing tables | 0.000028 | 0.000022 | 0.000006 |
| freeing items | 0.000035 | 0.000027 | 0.000008 |
| cleaning up | 0.000061 | 0.000048 | 0.000014 |
+----------------------+----------+----------+------------+
15 rows in set, 1 warning (0.00 sec)
mysql>
等等。
备注:分析在某些体系结构上仅部分起作用。对于依赖于 getrusage() 系统调用的值,在不支持该调用的系统(如 Windows)上将返回 NULL。此外,分析是按进程而不是按线程进行的。这意味着服务器中除您自己之外的线程上的活动可能会影响您看到的计时信息
3.使用Performance Schema进行查询分析
3.1 参数
该功能需要打开performance_schema
mysql> show variables like "performance_schema";
+--------------------+-------+
| Variable_name | Value |
+--------------------+-------+
| performance_schema | ON |
+--------------------+-------+
1 row in set (0.01 sec)
mysql>
3.2 测试
3.2.1 描述
以下示例演示了如何使用 Performance Schema 语句事件和阶段事件来检索与 SHOW PROFILES 和 SHOW PROFILE 语句提供的分析信息相当的数据。
setup_actors 表可用于限制主机、用户或帐户对历史事件的收集,以减少运行时开销和历史表中收集的数据量。该示例的第一步显示了如何将历史事件的收集限制为特定用户。
Performance Schema 以皮秒(万亿分之一秒)为单位显示事件计时器信息,以将计时数据规范化为标准单位。在以下示例中,TIMER_WAIT 值除以 1000000000000 以显示以秒为单位的数据。值也被截断到 6 个小数位,以与 SHOW PROFILES 和 SHOW PROFILE 语句相同的格式显示数据。
将历史事件的收集限制为运行查询的用户。默认情况下,setup_actors 被配置为允许对所有前台线程进行监控和历史事件收集。
3.2.2 查看setup_actors表
mysql> SELECT * FROM performance_schema.setup_actors;
+------+------+------+---------+---------+
| HOST | USER | ROLE | ENABLED | HISTORY |
+------+------+------+---------+---------+
| % | % | % | YES | YES |
+------+------+------+---------+---------+
1 row in set (0.00 sec)
备注:默认是%,并且ENABLED&HISTORY都为yes,说明默认是所有用户的操作都会记录
3.2.3 通过修改setup_actors增加所要收集用户
mysql> UPDATE performance_schema.setup_actors
SET ENABLED = 'NO', HISTORY = 'NO'
WHERE HOST = '%' AND USER = '%';
mysql> INSERT INTO performance_schema.setup_actors
(HOST,USER,ROLE,ENABLED,HISTORY)
VALUES('localhost','root','%','YES','YES');
mysql> SELECT * FROM performance_schema.setup_actors;
+-----------+------+------+---------+---------+
| HOST | USER | ROLE | ENABLED | HISTORY |
+-----------+------+------+---------+---------+
| % | % | % | NO | NO |
| localhost | root | % | YES | YES |
+-----------+------+------+---------+---------+
2 rows in set (0.00 sec)
mysql>
备注:只收集本地root用户的SQL执行历史事件。
3.2.4 两个基本概念
instruments: 生产者,用于采集mysql中各种各样的操作产生的事件信息,对应配置表中的配置项我们可以称为监控采集配置项。
consumers:消费者,对应的消费者表用于存储来自instruments采集的数据,对应配置表中的配置项我们可以称为消费存储配置项。
3.2.5 配置表setup_instruments
启用statement(语句事件)和stage(阶段事件)。statement默认是打开的
mysql> UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME LIKE '%statement/%';
mysql> UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME LIKE '%stage/%';
3.2.6 配置表setup_consumers
mysql> UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME LIKE '%events_statements_%';
mysql> UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE NAME LIKE '%events_stages_%';
3.2.7 在您正在监控的用户帐户下,运行您要分析的语句。例如:
mysql> select * from sbtest1 where id=2408;
+------+-------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| id | k | c | pad |
+------+-------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| 2408 | 50441 | 41261571371-82857935295-04772076407-90240978204-76323045802-82156837574-92691795833-99440060992-05916035775-36922661965 | 48505774068-01684540697-56990474665-04463857316-82195358005 |
+------+-------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
1 row in set (0.01 sec)
mysql>
3.2.8 查询
通过查询 events_statements_history_long 表来识别语句的 EVENT_ID。此步骤类似于运行 SHOW PROFILES 来识别 Query_ID。以下查询产生类似于 SHOW PROFILES 的输出:
mysql> SELECT EVENT_ID,TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%2408%';
+----------+----------+----------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EVENT_ID | Duration | SQL_TEXT |
+----------+----------+----------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 231 | 0.000942 | select * from test.sbtest1 where id=2408 |
| 282 | 0.011503 | SELECT EVENT_ID,TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%2408%' |
| 389 | 0.048925 | SELECT EVENT_ID,TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%2408%' |
| 405 | 0.025456 | SELECT EVENT_ID,TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%2408%' |
| 421 | 0.025546 | SELECT EVENT_ID,TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%2408%' |
+----------+----------+----------------------------------------------------------------------------------------------------------------------------------------------------------------+
5 rows in set (0.03 sec)
#由于使用DMP平台上的数据库,数据刷新很快,所以我用421往下测试
阶段使用事件嵌套链接到语句。每个阶段事件记录都有一个 NESTING_EVENT_ID 列,其中包含父语句的 EVENT_ID。
mysql> SELECT event_name AS Stage, TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration FROM performance_schema.events_stages_history_long WHERE NESTING_EVENT_ID=421;
+--------------------------------+----------+
| Stage | Duration |
+--------------------------------+----------+
| stage/sql/starting | 0.000350 |
| stage/sql/checking permissions | 0.000033 |
| stage/sql/Opening tables | 0.000054 |
| stage/sql/init | 0.000086 |
| stage/sql/System lock | 0.000024 |
| stage/sql/optimizing | 0.000023 |
| stage/sql/statistics | 0.000039 |
| stage/sql/preparing | 0.000057 |
| stage/sql/executing | 0.000017 |
| stage/sql/Sending data | 0.024741 |
| stage/sql/end | 0.000015 |
| stage/sql/query end | 0.000019 |
| stage/sql/closing tables | 0.000025 |
| stage/sql/freeing items | 0.000053 |
| stage/sql/cleaning up | 0.000001 |
+--------------------------------+----------+
15 rows in set (0.00 sec)
mysql>
#这个可以达到show profile的效果了