通过上面的描述可知， 当我们通过应用程序访问 MySQL 服务时， 有时候性能不一定全部卡在语句的执行上。 当然通过慢查询日志定位那些执行效率较低的SQL 语句时候我们常用的手段， 但是：
一、 慢查询日志在查询结束以后才记录， 在应用反映执行效率出现问题的时候查询未必执行完成；
二、 有时候问题的产生不一定是语句的执行， 有可能是其他原因导致的。 慢查询日志并不能定位问题。
show processlist
mysql> show processlist;
+----+------+-----------+------+---------+------+-------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+------+---------+------+-------------+------------------+
| 63 | root | localhost | NULL | Query | 0 | System lock | show processlist |
+----+------+-----------+------+---------+------+-------------+------------------+
1 row in set (0.00 sec)
这个时候通过 show processlist;查看线程状态非常有用,这可以让我们很快地了解当前 MySQL 在进行的线程,包括线程的状态、 是否锁表等， 可以实时地查看SQL 的执行情况， 同时对一些锁表操作进行优化。 在一个繁忙的服务器上， 可能会看到大量的不正常的状态， 例如 statistics 正占用大量的时间。 这通常表示， 某个地方有异常了。 线程常见的状态有很多， 比如
- statistics
The server is calculating statistics to develop a query execution plan. If a threadis in this state for a long time, the server is probably disk-bound performing otherwork.
服务器正在计算统计信息以研究一个查询执行计划。 如果线程长时间处于此状态， 则服务器可能是磁盘绑定执行其他工作。 - Creating tmp table
The thread is creating a temporary table in memory or on disk. If the table is created in memory but later is converted to an on-disk table, the state during that operation is Copying to tmp table on disk.
该线程正在内存或磁盘上创建临时表。 如果表在内存中创建但稍后转换为磁盘表， 则该操作期间的状态将为 Copying to tmp table on disk - Sending data
The thread is reading and processing rows for a SELECT statement, and sending data to the client. Because operations occurring during this state tend to perform large amounts of disk access (reads), it is often the longest-running state over the lifetime of a given query.
线程正在读取和处理 SELECT 语句的行 ， 并将数据发送到客户端。 由于在此状态期间发生的操作往往会执行大量磁盘访问（读取） ， 因此它通常是给定查询生命周期中运行时间最长的状态
参考官方文档：https://dev.mysql.com/doc/refman/5.7/en/general-thread-states.html
show profile
对于每个线程到底时间花在哪里， 可以通过 show profile 来分析。
1、 首先检查当前 MySQL 是否支持 profile
mysql> select @@have_profiling;
+------------------+
| @@have_profiling |
+------------------+
| YES |
+------------------+
1 row in set, 1 warning (0.00 sec)
2、 默认 profiling 是关闭的， 可以通过 set 语句在 Session 级别开启 profiling:
select @@profiling;
set profiling=1;
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 0 |
+-------------+
1 row in set, 1 warning (0.00 sec)
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
| 1 |
+-------------+
1 row in set, 1 warning (0.00 sec)
3、 执行一个 SQL 查询
select count(*) from order_exp;
4、 通过 show profiles 语句， 看到当前 SQL 的 Query ID
show profiles;
mysql> use test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Database changed
mysql> select count(*) from order_exp;
+----------+
| count(*) |
+----------+
| 10567 |
+----------+
1 row in set (0.01 sec)
mysql> show profiles;
+----------+------------+--------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------+
| 1 | 0.00034400 | select @@profiling |
| 2 | 0.00023950 | select count(*) from order_exp |
| 3 | 0.00050475 | SELECT DATABASE() |
| 4 | 0.00095700 | show databases |
| 5 | 0.00055825 | show tables |
| 6 | 0.00665250 | select count(*) from order_exp |
+----------+------------+--------------------------------+
6 rows in set, 1 warning (0.00 sec)
5、 通过 show profile for query 语句能够看到执行过程中线程的每个状态和消
耗的时间
show profile for query 6;
mysql> show profile for query 6;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000171 |
| Opening tables | 0.000030 |
| System lock | 0.000112 |
| checking permissions | 0.000016 |
| Opening tables | 0.000029 |
| init | 0.000067 |
| System lock | 0.000025 |
| optimizing | 0.000077 |
| statistics | 0.000031 |
| preparing | 0.000023 |
| executing | 0.000009 |
| Sending data | 0.005908 |
| end | 0.000025 |
| query end | 0.000032 |
| closing tables | 0.000019 |
| freeing items | 0.000049 |
| cleaning up | 0.000031 |
+----------------------+----------+
17 rows in set, 1 warning (0.02 sec)
通过仔细检查 show profile for query 的输出， 能够发现在执行 COUNT(*)的过程中， 时间主要消耗在 Sending data 这个状态上。
6、 在获取到最消耗时间的线程状态后， MySQL 支持进一步选择 all、 cpu、block io、 contextswitch、 page faults 等明细类型来查看 MySQL 在使用什么资源上耗费了过高的时间:
show profile all for query 6\G
mysql> show profile all for query 6\G
*************************** 1. row ***************************
Status: starting
Duration: 0.000171
CPU_user: 0.000000
CPU_system: 0.000164
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: NULL
Source_file: NULL
Source_line: NULL
*************************** 2. row ***************************
Status: Opening tables
Duration: 0.000030
CPU_user: 0.000000
CPU_system: 0.000030
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: open_ltable
Source_file: sql_base.cc
Source_line: 6490
*************************** 3. row ***************************
Status: System lock
Duration: 0.000112
CPU_user: 0.000013
CPU_system: 0.000099
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_lock_tables
Source_file: lock.cc
Source_line: 330
*************************** 4. row ***************************
Status: checking permissions
Duration: 0.000016
CPU_user: 0.000007
CPU_system: 0.000009
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: check_access
Source_file: sql_authorization.cc
Source_line: 809
*************************** 5. row ***************************
Status: Opening tables
Duration: 0.000029
CPU_user: 0.000012
CPU_system: 0.000017
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: open_tables
Source_file: sql_base.cc
Source_line: 5815
*************************** 6. row ***************************
Status: init
Duration: 0.000067
CPU_user: 0.000028
CPU_system: 0.000039
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: handle_query
Source_file: sql_select.cc
Source_line: 128
*************************** 7. row ***************************
Status: System lock
Duration: 0.000025
CPU_user: 0.000000
CPU_system: 0.000084
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_lock_tables
Source_file: lock.cc
Source_line: 330
*************************** 8. row ***************************
Status: optimizing
Duration: 0.000077
CPU_user: 0.000000
CPU_system: 0.000018
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 158
*************************** 9. row ***************************
Status: statistics
Duration: 0.000031
CPU_user: 0.000000
CPU_system: 0.000030
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 374
*************************** 10. row ***************************
Status: preparing
Duration: 0.000023
CPU_user: 0.000000
CPU_system: 0.000023
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: optimize
Source_file: sql_optimizer.cc
Source_line: 482
*************************** 11. row ***************************
Status: executing
Duration: 0.000009
CPU_user: 0.000000
CPU_system: 0.000010
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 126
*************************** 12. row ***************************
Status: Sending data
Duration: 0.005908
CPU_user: 0.005915
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 1
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 202
*************************** 13. row ***************************
Status: end
Duration: 0.000025
CPU_user: 0.000018
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: handle_query
Source_file: sql_select.cc
Source_line: 206
*************************** 14. row ***************************
Status: query end
Duration: 0.000032
CPU_user: 0.000031
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_execute_command
Source_file: sql_parse.cc
Source_line: 4959
*************************** 15. row ***************************
Status: closing tables
Duration: 0.000019
CPU_user: 0.000018
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_execute_command
Source_file: sql_parse.cc
Source_line: 5018
*************************** 16. row ***************************
Status: freeing items
Duration: 0.000049
CPU_user: 0.000050
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: mysql_parse
Source_file: sql_parse.cc
Source_line: 5637
*************************** 17. row ***************************
Status: cleaning up
Duration: 0.000031
CPU_user: 0.000030
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 0
Swaps: 0
Source_function: dispatch_command
Source_file: sql_parse.cc
Source_line: 1933
17 rows in set, 1 warning (0.00 sec)
其中
*************************** 12. row ***************************
Status: Sending data
Duration: 0.005908
CPU_user: 0.005915
CPU_system: 0.000000
Context_voluntary: 0
Context_involuntary: 0
Block_ops_in: 0
Block_ops_out: 0
Messages_sent: 0
Messages_received: 0
Page_faults_major: 0
Page_faults_minor: 1
Swaps: 0
Source_function: exec
Source_file: sql_executor.cc
Source_line: 202
能够发现 Sending data 状态下， 时间主要消耗在 CPU 上了。所以show profile能够在做SQL优化时帮助我们了解时间都耗费到哪里去了，同时如果 MySQL 源码感兴趣， 还可以通过 show profile source for query 查看 SQL解析执行过程中每个步骤对应的源码的文件、 函数名以及具体的源文件行数。