本文共 6996 字，大约阅读时间需要 23 分钟。
MySQL 从5.0.37版本开始增加了show profiles 和show profile 语句的支持。通过have_profiling参数，能够看到have_profiling参数，能够看到当前MySQL是否支持profile：
mysql> select @@have_profiling;+------------------+| @@have_profiling |+------------------+| YES |+------------------+1 row in set (0.00 sec)
默认profiling是关闭的，可以通过set语句在Session级别开启profiling；
mysql> select @@profiling;+-------------+| @@profiling |+-------------+| 0 |+-------------+1 row in set (0.00 sec)mysql> set profiling=1;Query OK, 0 rows affected (0.01 sec)
通过profile，我们能够更清楚第了解SQL执行的过程。例如，我们知道MyISAM表有元数据的缓存（例如行数，即COUNT(*) 值）。 那么对一个MyISAM表的count（*）的不需要消耗太多资源的，而对于InnoDB来说，就没有这种元数据缓存，COUNT(*)执行的较慢。下面来做个实验验证一下:
首先，在一个InnoDB引擎的付款表上payment上，执行一个COUNT(*)查询：
mysql> select count(*) from payment;+----------+| count(*) |+----------+| 16049 |+----------+1 row in set (0.45 sec)
执行完毕后，通过show profiles 语句，看到当前SQL的Query _ID 为1：
mysql> show profiles;+----------+------------+------------------------------+| Query_ID | Duration | Query |+----------+------------+------------------------------+| 1 | 0.44651650 | select count(*) from payment |+----------+------------+------------------------------+1 row in set (0.00 sec)
通过show profile for query 语句能够看到执行过程中线程的每个状态和消耗的时间：
mysql> show profile for query 1;+----------------------+----------+| Status | Duration |+----------------------+----------+| starting | 0.000199 || checking permissions | 0.012579 || Opening tables | 0.228322 || System lock | 0.000091 || init | 0.000015 || optimizing | 0.000004 || statistics | 0.000012 || preparing | 0.000007 || executing | 0.000004 || Sending data | 0.175927 || end | 0.029246 || query end | 0.000018 || closing tables | 0.000011 || freeing items | 0.000068 || logging slow query | 0.000003 || cleaning up | 0.000012 |+----------------------+----------+16 rows in set (0.18 sec)
注意： Sending data状态表示MySQL线程开始访问数据行并把结果返回给客户端，而不仅仅是返回结果给客户端。
由于在Sending data状态下，MySQL线程往往需要做大量的磁盘读取操作，所以经常是整个查询中耗时最长的状态。
通过仔细检查show profile for query 的输出，能够发现在执行 COUNT(*) 的过程中，时间主要消耗在Sending data 这个状态上。为了更清晰地看到排序结果，可以查询INFROMATION_SCHEMA.PROFILING 表并按照时间做个DESC排序。
mysql> 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 |+--------------------+----------+-------+-------+--------------+| starting | 0.000478 | 56.97 | 1 | 0.0004780000 || freeing items | 0.000327 | 38.97 | 1 | 0.0003270000 || logging slow query | 0.000026 | 3.10 | 1 | 0.0000260000 || cleaning up | 0.000008 | 0.95 | 1 | 0.0000080000 |+--------------------+----------+-------+-------+--------------+4 rows in set (0.09 sec)
在获取到最消耗时间的线程状态后，MySQL 支持进一步选择all、cpu、block io、context switch、 page faults 等明细类型来查看MySQL在使用什么资源上耗费了过高的时间，例如，选择查看CPU的耗费时间：
mysql> show profile cpu for query 1;+----------------------+----------+----------+------------+| Status | Duration | CPU_user | CPU_system |+----------------------+----------+----------+------------+| starting | 0.000199 | 0.000000 | 0.000000 || checking permissions | 0.012579 | 0.000000 | 0.000000 || Opening tables | 0.228322 | 0.000000 | 0.000000 || System lock | 0.000091 | 0.000000 | 0.000000 || init | 0.000015 | 0.000000 | 0.000000 || optimizing | 0.000004 | 0.000000 | 0.000000 || statistics | 0.000012 | 0.000000 | 0.000000 || preparing | 0.000007 | 0.000000 | 0.000000 || executing | 0.000004 | 0.000000 | 0.000000 || Sending data | 0.175927 | 0.000000 | 0.000000 || end | 0.029246 | 0.000000 | 0.000000 || query end | 0.000018 | 0.000000 | 0.000000 || closing tables | 0.000011 | 0.000000 | 0.000000 || freeing items | 0.000068 | 0.000000 | 0.000000 || logging slow query | 0.000003 | 0.000000 | 0.000000 || cleaning up | 0.000012 | 0.000000 | 0.000000 |+----------------------+----------+----------+------------+
能够发现Sending data状态下，时间主要消耗在CPU 上了。
对比 MyISAM 表的 COUNT(*) 操作，也创建一个同样表结构的MyISAM 表，数据量也完全一致：
mysql> create table payment_myisam like payment;Query OK, 0 rows affected (0.78 sec)mysql> alter table payment_myisam engine = myisam;Query OK, 0 rows affected (0.42 sec)Records: 0 Duplicates: 0 Warnings: 0mysql> insert into payment_myisam select * from payment;Query OK, 16049 rows affected (0.46 sec)Records: 16049 Duplicates: 0 Warnings: 0
同样执行COUNT(*) 操作，检查profile：
mysql> select count(*) from payment_myisam;+----------+| count(*) |+----------+| 16049 |+----------+1 row in set (0.00 sec)....mysql> show profiles;....mysql> show profile for query 12;+----------------------+----------+| Status | Duration |+----------------------+----------+| starting | 0.000093 |....| executing | 0.000017 || end | 0.000005 || query end | 0.000003 |.....| cleaning up | 0.000002 |+----------------------+----------+13 rows in set (0.00 sec)
从profile 的结果能够看出，InnoDB引擎的表在COUNT(*)时经历了Sending data 状态，存在访问数据的过程，而MyISAM引擎的表在executing 之后直接就结束查询，完全不需要访问数据。
如果你对MySQL源码感兴趣，还可以通过show profile source for query 查看SQL解析执行过程中每个步骤对应的源码文件、函数名以及具体的源文件行数：
mysql> show profile source for query 12;+----------------------+----------+-----------------+---------------+-------------+| Status | Duration | Source_function | Source_file | Source_line |+----------------------+----------+-----------------+---------------+-------------+| starting | 0.000093 | NULL | NULL | NULL || checking permissions | 0.000011 || sql_parse.cc | 4745 || Opening tables | 0.000026 | | sql_base.cc | 4836 || System lock | 0.000014 | | lock.cc | 299 || init | 0.000015 | | sql_select.cc | 2554 || optimizing | 0.000007 | | sql_select.cc | 863 || executing | 0.000017 | | sql_select.cc | 1823 || end | 0.000005 | | sql_select.cc | 2590 || query end | 0.000003 | | sql_parse.cc | 4434 || closing tables | 0.000007 | | sql_parse.cc | 4486 || freeing items | 0.000039 | | sql_parse.cc | 5634 || logging slow query | 0.000002 | | sql_parse.cc | 1460 || cleaning up | 0.000002 | | sql_parse.cc | 1416 |+----------------------+----------+-----------------+---------------+-------------+
转载地址：http://adfoi.baihongyu.com/