超详细用profile工具分析sql语句执行及status说明

超详细用profile工具分析sql语句执行及status说明

介绍

sql执行慢的原因有可能很多种，怎么定位呢？可以用Query Profile人工具。通过该工具可以获取一条Query 在整个执行过程中多种资源的消耗情况，如 CPU，IO，IPC，SWAP 等，以及发生的 PAGE FAULTS，CONTEXT SWITCHE 等等，同时还能得到该 Query 执行过程中 MySQL 所调用的各个函数在源文件中的位置。

但是因为它需要调用系统的getrusage()函数，所以只是在Linux/Unix类平台上才能使用，而不能在Windows平台上使用。而且，PROFILING是针对处理进程(process)而不是线程(thread)的，服务器上的其他应用，可能会影响您的调试结果，因此，这个工具适合开发过程中的调试，如果要在生产环境中调试使用，则要注意它的局限性。

操作

mysql> show variables like '%profil%' // 查看profiling监控是否打开
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
mysql> set profiling=1; // 开启profiling监听，注意区分全局变量和session变量，全局用set global profiling
mysql> select * from users where id = 1; // 执行任意sql语句
mysql> show profiles; // 查看记录到的query
+----------+------------+----------------------------+
| Query_ID | Duration   | Query                      |
+----------+------------+----------------------------+
|        1 | 0.00060275 | select * from customers    |
|        2 | 0.00222450 | show tables                |
|        3 | 0.00567425 | select * from offices      |
|        4 | 0.00052050 | show tables                |
|        5 | 0.01123300 | select * from payments     |
|        6 | 0.00111675 | show tables                |
|        7 | 0.02049625 | select * from users where id = 1 |
+----------+------------+----------------------------+
mysql> show profile for query 7;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000043 |
| checking permissions | 0.000005 |
| Opening tables       | 0.014552 |
| init                 | 0.000025 |
| System lock          | 0.000009 |
| optimizing           | 0.000004 |
| statistics           | 0.000011 |
| preparing            | 0.000010 |
| executing            | 0.000003 |
| Sending data         | 0.005653 |
| end                  | 0.000010 |
| query end            | 0.000009 |
| closing tables       | 0.000020 |
| freeing items        | 0.000121 |
| cleaning up          | 0.000023 |
+----------------------+----------+
mysql> show profile block io, cpu for query 7; //获取io和cpu详细消耗信息
mysql> show profile block io, cpu, memory, swaps, context switches, source for query 7; //获取其他详细消耗信息如，内存，虚拟内存，上下文切换

status说明

通过上面的信息，可以看到很多内容，注意mysql show proflie 的 status信息。通过在哪一个status耗时比较长可以帮助我们定位问题。

altering table
服务器正在执行一个ALTER TABLE

checking permissions
线程正在检查服务器是否拥有执行语句所需的权限。

Checking table
线程正在执行一个表检查操作。

cleaning up
线程已经处理了一个命令，并准备释放内存和重置某些状态变量。

Closing tables	
正在将表中修改的数据刷新到磁盘中，同时正在关闭已经用完的表。这是一个很快的操作，如果不是，请检查磁盘是否已满，磁盘是否被大量使用。

copy to tmp table
线程正在处理一条ALTER TABLE语句。这种状态发生在创建了具有新结构的表之后，但在将行复制到该表之前。

Copying to tmp table on disk	
由于临时结果集大于tmp_table_size，正在将临时表从内存存储转为磁盘存储以此节省内存。

deleting from main table
服务器正在执行多表删除的第一部分。它只删除第一个表，并保存用于从其他(引用)表删除的列和偏移量。

deleting from reference tables
服务器正在执行多表删除的第二部分，并从其他表中删除匹配的行。

end
这发生在ALTER TABLE、CREATE VIEW、DELETE、INSERT、SELECT或UPDATE语句清理之前的末尾。
对于结束状态，可能会发生以下操作:
1、修改表中的数据后删除查询缓存项
2、将事件写入二进制日志
3、释放内存缓冲区，包括用于blob的缓冲区

executing
线程开始执行一条语句。

init
这发生在ALTER TABLE、DELETE、INSERT、SELECT或UPDATE语句初始化之前。在这种状态下，服务器采取的操作包括清空二进制日志、InnoDB日志和一些查询缓存清理操作。

Killed
发送了一个kill请求给某线程，那么这个线程将会检查kill标志位，同时会放弃下一个kill请求。MySQL会在每次的主循环中检查kill标志位，不过有些情况下该线程可能会过一小段才能死掉。如果该线程程被其他线程锁住了，那么kill请求会在其他线程释放锁时生效。

logging slow query
线程正在向慢查询日志写入一条语句。

manage keys
服务器正在启用或禁用一个表索引。

Opening tables
线程试图打开一个表。这应该是一个非常快的过程，除非有什么东西阻止打开。例如，ALTER TABLE或LOCK TABLE语句可以阻止打开一个表，直到语句完成。还需要检查table_open_cache值是否足够大。

optimizing
服务器正在对查询执行初始优化。

query end
此状态发生在处理查询之后，但在释放项状态之前。如果发现这里耗时严重，参考end状态的说明

Removing duplicates
查询使用SELECT DISTINCT的方式，MySQL不能在早期阶段优化掉DISTINCT操作。因此，MySQL在将结果发送到客户端之前需要一个额外的阶段来删除所有重复的行。

removing tmp table
线程正在处理一个SELECT语句后删除一个内部临时表。如果没有创建临时表，则不使用此状态。

Receiving from client
服务器正在从客户端读取数据包。在MySQL 5.7.8之前，这个状态叫做Reading from net。

Reopen tables
线程获得了表的锁，但在获得锁后注意到底层表结构发生了变化。它释放了锁，关闭了表，并试图重新打开它。

Rolling back
线程正在回滚事务。

starting
语句执行开始的第一个阶段。

Sending data
线程正在读取和处理SELECT语句的行，并向客户机发送数据。由于在此状态下发生的操作往往会执行大量的磁盘访问(读取)，因此在给定查询的生命周期中，它通常是运行时间最长的状态。

Sorting for group
线程正在进行排序，以满足GROUP BY的要求。

Sorting for order
线程正在执行排序以满足ORDER BY。

statistics
服务器正在计算统计数据以制定查询执行计划。如果一个线程长时间处于这种状态，那么服务器可能是磁盘绑定的，正在执行其他工作。

System lock
线程调用了mysql_lock_tables()，并且线程状态一直没有更新。这是一种非常普遍的状态，可能由于许多原因而发生。
例如，线程将请求或等待表的内部或外部系统锁。当InnoDB在执行锁表时等待表级锁时，就会发生这种情况。如果这种状态是由外部锁请求引起的，并且您没有使用多个正在访问相同MyISAM表的mysqld服务器，您可以使用——skip-external-locking选项禁用外部系统锁。但是，外部锁定在默认情况下是禁用的，所以这个选项很可能没有效果。对于SHOW PROFILE，这个状态意味着线程正在请求锁(而不是等待锁)。

update
线程已经准备好开始更新表。

Updating
线程正在搜索要更新的行，并正在更新它们。

updating main table
服务器正在执行多表更新的第一部分。它只更新第一个表，并保存用于更新其他(引用)表的列和偏移量。

updating reference tables
服务器正在执行多表更新的第二部分，并更新来自其他表的匹配行。

User lock
线程正在请求或等待用GET_LOCK()调用请求的建议锁。对于SHOW PROFILE，这个状态意味着线程正在请求锁(而不是等待锁)。

User sleep
线程调用了一个SLEEP()调用。

Waiting for commit lock
带读锁的FLUSH TABLES正在等待提交锁。

Waiting for global read lock
带读锁的FLUSH TABLES正在等待一个全局读锁，或者正在设置全局read_only系统变量。

Waiting for tables
线程收到一个通知，说表的底层结构发生了变化，它需要重新打开表以获得新的结构。但是，要重新打开表，它必须等待所有其他线程都关闭了相关的表。

Waiting for lock_type lock
服务器正在等待获取THR_LOCK锁或者元数据锁，其中lock_type表示锁的类型。

下面这个状态表示等待THR_LOCK锁:
Waiting for table level lock

下面这些状态表示等待元数据锁（metadata lock）
Waiting for event metadata lock
Waiting for global read lock
Waiting for schema metadata lock
Waiting for stored function metadata lock
Waiting for stored procedure metadata lock
Waiting for table metadata lock
Waiting for trigger metadata lock

案例说明

测试中发现一条insert语句执行居然要耗时70-140MS。通过profile发现在query end耗时居然非常多，一番查询下来，发现有三种情况可以解释上面的状况

硬盘快满了

 首先排除了

sync_binlog=1导致

• 值为1：事务提交后，将二进制文件写入磁盘并立即执行刷新操作，相当于是同步写入磁盘，不经过操作系统的缓存。虽然能够保证事务原子性，但是验证影响写入速度。和0的写入速度能相差30倍左右。
• 值为0：默认值。事务提交后，将二进制日志从缓冲写入磁盘，但是不进行刷新操作（fsync()），此时只是写入了操作系统缓冲，若操作系统宕机则会丢失部分二进制日志。
• 值为N：每写N次操作系统缓冲就执行一次刷新操作。

innodb_flush_log_at_trx_commit=1导致

• 值为0 : 提交事务的时候，不立即把 redo log buffer 里的数据刷入磁盘文件的，而是依靠 InnoDB 的主线程每秒执行一次刷新到磁盘。此时可能你提交事务了，结果 mysql 宕机了，然后此时内存里的数据全部丢失。
• 值为1 : 提交事务的时候，就必须把 redo log 从内存刷入到磁盘文件里去，只要事务提交成功，那么 redo log 就必然在磁盘里了。注意，因为操作系统的“延迟写”特性，此时的刷入只是写到了操作系统的缓冲区中，因此执行同步操作才能保证一定持久化到了硬盘中。
• 值为2 : 提交事务的时候，把 redo 日志写入磁盘文件对应的 os cache 缓存里去，而不是直接进入磁盘文件，可能 1 秒后才会把 os cache 里的数据写入到磁盘文件里去。
• 可以看到，只有1才能真正地保证事务的持久性，但是由于刷新操作 fsync() 是阻塞的，直到完成后才返回，我们知道写磁盘的速度是很慢的，因此 MySQL 的性能会明显地下降。如果不在乎事务丢失，0和2能获得更高的性能。

最后发现和sync_binlog=1强相关，改为0以后写入速度有显著提升。但是该选项的设置还要根据具体业务场景来确定用什么策略比较合适。

要废弃

但是，从5.7版本的refman文档(mysql-refman-5.7)就有在说明这两个命令会废弃掉，要用其他performance schema替代。

Note
The SHOW PROFILE and SHOW PROFILES statements are deprecated; expect them to be removed in a future MySQL release. Use the Performance Schema instead; see Section 25.19.1, “Query Profiling Using Performance Schema”.