mysql profile使用场景及方法
今天有客户反馈，同样的SQL和同样数据量的数据库在RDS和自建库上面，执行时间差异非常大，需要排查一下具体的原因，当时用了show profile给客户说明了具体时间花费在哪一步。首先当然看下具体情况、数据量、索引、执行计划等是否真的如客户所说完全一致，当然这不在我们这篇文档的范围内。
今天我们主要来讲一下mysql show profile查看SQL执行的时间到底去哪了。
准备工作
相关参数:
[profiling] 控制是否开启profiling，值为bool，默认为off。
[profiling_history_size] 控制保存的statement数量，默认为15，上限100，设置为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
}
使用profile之前，我们先要开启profiling，默认该参数是关闭的，我们可以会话级别设置开启来进行临时测试。
| mysql> show variables like 'profiling'; | |
|---|---|
| Variable_name | Value |
| profiling | OFF |
1 row in set (0.00 sec)
mysql> set session profiling = 1;
执行SQL：
select * from class_a_score where id = 1;
| mysql> show variables like 'profiling_history_size'; | |
|---|---|
| Variable_name | Value |
| profiling_history_size | 15 |
SHOW profiles 结果：show profiles 是查看所有在history size（当前为15）的语句执行花费的时间和具体SQL语句。
| mysql> show profiles; | ||
|---|---|---|
| Query_ID | Duration | Query |
| 1 | 0.00034000 | explain select * from class_a_score where id = 1 |
| 2 | 0.00304225 | show variables like 'profiling_history_size' |
指定上面SQL_ID，查看具体的query，每个阶段所花费的时间。（注意，show profile只显示上一条SQL的结果）
这里的status，就是show processlist中类似的结果。[可以另外加limit 和 offset 来控制输出内容]
| mysql> show profile for query 1; | |
|---|---|
| Status | Duration |
| starting | 0.000069 |
| checking permissions | 0.000011 |
| Opening tables | 0.000018 |
| init | 0.000027 |
| System lock | 0.000010 |
| optimizing | 0.000011 |
| statistics | 0.000041 |
| preparing | 0.000042 |
| explaining | 0.000041 |
| end | 0.000005 |
| query end | 0.000008 |
| closing tables | 0.000014 |
| freeing items | 0.000038 |
| cleaning up | 0.000005 |
14 rows in set, 1 warning (0.01 sec)
| mysql> show profile for query 1 limit 1; | |
|---|---|
| Status | Duration |
| starting | 0.000069 |
1 row in set, 1 warning (0.01 sec)
| mysql> show profile for query 1 limit 1 offset 2; | |
|---|---|
| Status | Duration |
| Opening tables | 0.000018 |
1 row in set, 1 warning (0.01 sec)
show profile 进阶
另外可以加上type 查看具体花费在CPU还是读写数据上等。
| mysql> show profile cpu; | |||
|---|---|---|---|
| Status | Duration | CPU_user | CPU_system |
| starting | 0.000065 | 0.000000 | 0.000053 |
| checking permissions | 0.000011 | 0.000000 | 0.000010 |
| Opening tables | 0.000019 | 0.000000 | 0.000018 |
| init | 0.000016 | 0.000000 | 0.000016 |
| System lock | 0.000010 | 0.000000 | 0.000010 |
| optimizing | 0.000006 | 0.000000 | 0.000006 |
| statistics | 0.000010 | 0.000000 | 0.000009 |
| preparing | 0.000009 | 0.000000 | 0.000009 |
| executing | 0.000005 | 0.000000 | 0.000005 |
| Sending data | 0.000482 | 0.000000 | 0.000483 |
| end | 0.000006 | 0.000000 | 0.000005 |
| query end | 0.000008 | 0.000000 | 0.000009 |
| closing tables | 0.000008 | 0.000000 | 0.000008 |
| freeing items | 0.000051 | 0.000000 | 0.000060 |
| cleaning up | 0.000014 | 0.000000 | 0.000005 |
15 rows in set, 1 warning (0.01 sec)
这个就是因为时间都花费在物理读上面，导致执行时间过长。
在performance_schema中的应用
因为官方文档中指出，可能再不久将来会废除show profile（因为确实有局限性，比如只能在当前会话使用），目前已经支持使用performance_schema来查看，如下是开启过程：
1、查看是否需要限制哪些前端线程会被记录
SELECT * FROM performance_schema.setup_actors;
INSERT INTO performance_schema.setup_actors
(HOST,USER,ROLE,ENABLED,HISTORY)
VALUES('localhost','test_user','%','YES','YES');
2、开启统计timer和eventUPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE (NAME LIKE '%statement/%' or NAME LIKE '%stage/%');
UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES'
WHERE (NAME LIKE '%events_statements_%' or NAME LIKE '%events_stages_%');
3.查找出来event_id
SELECT EVENT_ID, TRUNCATE(TIMER_WAIT/1000000000000,6) as Duration, SQL_TEXT
FROM performance_schema.events_statements_history_long WHERE SQL_TEXT like '%sql_text%'
4.把上一步查出来event_id带入
SELECT event_name AS Stage, TRUNCATE(TIMER_WAIT/1000000000000,6) AS Duration
FROM performance_schema.events_stages_history_long WHERE NESTING_EVENT_ID=<?>;
查考：
https://dev.mysql.com/doc/refman/5.6/en/show-profile.html