mysql调优：SHOW PROFILES 剖析sql执行详情

使用介绍

SHOW PROFILE 命令是在 MYSQL 5.1 之后的版本中引入的，来源于开源社区中的Jeremy Cole 的贡献。这条命令会在服务器上执行的所有语句都去测量其耗费的时间和其他的一些查询执行状态变更的相关数据，这些测量的数据目前是存储在 information_schema.PROFILING 表中。
默认 SHOW PROFILE 是禁用的，但是可以通过服务器变量在会话级别动态修改，注意这里是会话级别的，也就是本次会话结束这个设置就失效了。

mysql> set profiling =1;

开启后，当一条查询提交给服务器时，此工具会记录剖析这条sql的执行信息到一张临时表，并且给查询赋予一个整数标识符，然后返回回来。
如下命令

 select * from mysql_prefmance.integer_data;
 show profiles ;
 show profile for query 1;

执行过程

首先我们要执行一条sql语句做为本次会话分析的样本，共扫描了10001 行，只有主键索引，耗时0.02 sec

mysql> select * from mysql_prefmance.integer_data;
10001 rows in set (0.02 sec)

执行完sql之后，工具便可以收集到这条sql的信息了，如果要想分析这条sql的明细，我们还需要弄到QueryId，使用如下命令来查看当前的sql的queryId是多少。

mysql> show profiles ;
+----------+------------+--------------------------------------------+
| Query_ID | Duration   | Query                                      |
+----------+------------+--------------------------------------------+
|        1 | 0.01813250 | select * from mysql_prefmance.integer_data |
+----------+------------+--------------------------------------------+
1 row in set, 1 warning (0.00 sec)

可以看到这条sql的Query_ID为1，并且很高的精度显示了本次查询的响应时间，这比之间的简单的日志信息无疑详细了不少。

mysql> show profile for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000174 |
| Executing hook on transaction  | 0.000008 |
| starting                       | 0.000024 |
| checking permissions           | 0.000018 |
| Opening tables                 | 0.000656 |
| init                           | 0.000038 |
| System lock                    | 0.000025 |
| optimizing                     | 0.000009 |
| statistics                     | 0.000029 |
| preparing                      | 0.000033 |
| executing                      | 0.005896 |
| end                            | 0.000010 |
| query end                      | 0.000005 |
| waiting for handler commit     | 0.000017 |
| closing tables                 | 0.011048 |
| freeing items                  | 0.000116 |
| cleaning up                    | 0.000029 |
+--------------------------------+----------+
17 rows in set, 1 warning (0.00 sec)

拿到 Query_ID 后我们可以查看更精确的信息来剖析整条sql的执行详情，这条命令显示了查询执行的每个步骤所花费的时间。
注意要想使用这条命令，最好是在原生dom中操作，如果使用一些数据库客户度(dataGrip) 可能这种命令不会被支持，并且客户端会默认多搞一些额外操作导致统计不准确。

information_schema

如果不使用上边的命令，也可以统计 information_schema 库的 PROFILING 表，之前统计的信息其实都会放到这张表中。

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       |
+--------------------------------+----------+-------+-------+--------------+
| closing tables                 | 0.011048 | 60.92 |     1 | 0.0110480000 |
| executing                      | 0.005896 | 32.51 |     1 | 0.0058960000 |
| Opening tables                 | 0.000656 |  3.62 |     1 | 0.0006560000 |
| starting                       | 0.000198 |  1.09 |     2 | 0.0000990000 |
| freeing items                  | 0.000116 |  0.64 |     1 | 0.0001160000 |
| init                           | 0.000038 |  0.21 |     1 | 0.0000380000 |
| preparing                      | 0.000033 |  0.18 |     1 | 0.0000330000 |
| statistics                     | 0.000029 |  0.16 |     1 | 0.0000290000 |
| cleaning up                    | 0.000029 |  0.16 |     1 | 0.0000290000 |
| System lock                    | 0.000025 |  0.14 |     1 | 0.0000250000 |
| checking permissions           | 0.000018 |  0.10 |     1 | 0.0000180000 |
| waiting for handler commit     | 0.000017 |  0.09 |     1 | 0.0000170000 |
| end                            | 0.000010 |  0.06 |     1 | 0.0000100000 |
| optimizing                     | 0.000009 |  0.05 |     1 | 0.0000090000 |
| Executing hook on transaction  | 0.000008 |  0.04 |     1 | 0.0000080000 |
| query end                      | 0.000005 |  0.03 |     1 | 0.0000050000 |
+--------------------------------+----------+-------+-------+--------------+

这个结果比之前的更加明晰，不仅根据执行时间做了排序，还将一些执行操作做了统计，从上结果可以看出，时间主要花在了 executing 这个过程以及 closing tables 上，losing tables 通常是因为磁盘 IO 能力不足引起的，可以排查磁盘 IO 的占用。

各个状态一览表

状态	说明
Checking table	正在检查数据表（这是自动的）
Connect Out	复制从服务器正在连接主服务器
Closing tables	正在将表中修改的数据刷新到磁盘中，同时正在关闭已经用完的表。这是一个很快的操作，如果不是这样的话，就应该确认磁盘空间是否已经满了或者磁盘是否正处于重负中
Copying to tmp table on disk	由于临时结果集大于tmp_table_size，正在将临时表从内存存储转为磁盘存储以此节省内存
Creating tmp table	正在创建临时表以存放部分查询结果
deleting from main table	服务器正在执行多表删除中的第一部分，刚删除第一个表。
deleting from reference tables	服务器正在执行多表删除中的第二部分，正在删除其他表的记录。
Flushing tables	正在执行FLUSH TABLES，等待其他线程关闭数据表。
Killed	发送了一个kill请求给某线程，那么这个线程将会检查kill标志位，同时会放弃下一个kill请求。MySQL会在每次的主循环中检查kill标志位，不过有些情况下该线程可能会过一小段才能死掉。如果该线程程被其他线程锁住了，那么kill请求会在锁释放时马上生效。
Locked	被其他查询锁住了。
Sending data	正在处理SELECT查询的记录，同时正在把结果发送给客户端。
Sorting for group	正在为GROUP BY做排序。
Sorting for order	正在为ORDER BY做排序。
Opening tables	这个过程应该会很快，除非受到其他因素的干扰。例如，在执ALTER TABLE或LOCK TABLE语句行完以前，数据表无法被其他线程打开。正尝试打开一个表。
Removing duplicates	正在执行一个SELECT DISTINCT方式的查询，但是MySQL无法在前一个阶段优化掉那些重复的记录。因此，MySQL需要再次去掉重复的记录，然后再把结果发送给客户端。
Reopen table	获得了对一个表的锁，但是必须在表结构修改之后才能获得这个锁。已经释放锁，关闭数据表，正尝试重新打开数据表。
Repair by sorting	修复指令正在排序以创建索引。
Repair with keycache	修复指令正在利用索引缓存一个一个地创建新索引。它会比Repair by sorting慢些。
Searching rows for update	正在讲符合条件的记录找出来以备更新。它必须在UPDATE要修改相关的记录之前就完成了。
Sleeping	正在等待客户端发送新请求.
System lock	正在等待取得一个外部的系统锁。如果当前没有运行多个mysqld服务器同时请求同一个表，那么可以通过增加–skip-external-locking参数来禁止外部系统锁。
Upgrading lock	INSERT DELAYED正在尝试取得一个锁表以插入新记录。
Updating	正在搜索匹配的记录，并且修改它们。
User Lock	正在等待GET_LOCK()。
Waiting for tables	该线程得到通知，数据表结构已经被修改了，需要重新打开数据表以取得新的结构。然后，为了能的重新打开数据表，必须等到所有其他线程关闭这个表。以下几种情况下会产生这个通知：FLUSH TABLES tbl_name, ALTER TABLE,waiting for handler insert INSERT DELAYED已经处理完了所有待处理的插入操作，正在等待新的请求。
after create	线程创建一个表或临时表的最后会进入该状态
Analyzing	线程正在分析一个 MyISAM 表或索引描述（例如 ANALYZE TABLE）
checking permissions	线程在查看是否具有权限
Checking table	表检查操作
cleaning up	线程已处理了一个命令，正在准备释放内存和资源
closing tables	线程将更改的表数据刷新到磁盘并关闭使用的表
converting HEAP to MyISAM	线程正在将内存表中的内部临时表转换为磁盘上的 MyISAM 表
copy to tmp table	线程正在执行一条 alter table 语句，已创建新结构的表，正在将数据复制到新结构的表中
Copying to group table	一条语句的ORDER BY和GROUP BY条件不同时，将数据行按组排序并复制到临时表中
Copying to tmp table	复制数据到内存中的一张临时表中
Copying to tmp table on disk	由于临时结果集大于 tmp_table_size，所以线程正在将临时表从内存中更改为基于磁盘的格式保存
Creating index	线程正在对一个 MyISAM 表执行 ALTER TABLE … ENABLE KEYS
Creating sort index	正在执行一个使用内部临时表的查询
creating table	正在创建一个表（包括临时表）
Creating tmp table	线程正在内存或磁盘上创建一个临时表。如果表是在内存中创建的，但稍后被转换为磁盘上的表，则该操作期间的状态将复制到磁盘上的tmp表