MySQL中SHOW Profile进行sql分析

1.查询profiling

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

2.开启profiling

mysql> set profiling=on;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | ON    |
+---------------+-------+
1 row in set (0.00 sec)

查看profiles记录语句

mysql> Show profiles;
+----------+------------+---------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                     |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00118800 | show variables like 'profiling'                                                                                           |
|        2 | 0.16707350 | select count(1) from emp                                                                                                  |
|        3 | 0.00017950 | select * from emp group by id%10 limit 150000                                                                             |
|        4 | 0.00012400 | set session sql_mode='STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION' |
|        5 | 2.07893175 | select * from emp group by id%10 limit 150000                                                                             |
+----------+------------+---------------------------------------------------------------------------------------------------------------------------+
5 rows in set, 1 warning (0.00 sec)

在上面的查询结果中我们可以发现这里面的第五条sql查询时间超过两秒，因此可以仔细查看这条sql。

使用profile 分析sql

mysql> show profile cpu,block io for query 5;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000076 | 0.000072 |   0.000000 |            0 |             0 |
| Executing hook on transaction  | 0.000005 | 0.000003 |   0.000000 |            0 |             0 |
| starting                       | 0.000008 | 0.000008 |   0.000000 |            0 |             0 |
| checking permissions           | 0.000006 | 0.000006 |   0.000000 |            0 |             0 |
| Opening tables                 | 0.000036 | 0.000036 |   0.000000 |            0 |             0 |
| init                           | 0.000007 | 0.000006 |   0.000000 |            0 |             0 |
| System lock                    | 0.000009 | 0.000010 |   0.000000 |            0 |             0 |
| optimizing                     | 0.000006 | 0.000005 |   0.000000 |            0 |             0 |
| statistics                     | 0.000027 | 0.000028 |   0.000000 |            0 |             0 |
| preparing                      | 0.000012 | 0.000012 |   0.000000 |            0 |             0 |
| Creating tmp table             | 0.000055 | 0.000055 |   0.000000 |            0 |             0 |
| executing                      | 2.078602 | 1.042725 |   0.000000 |            0 |             0 |
| end                            | 0.000019 | 0.000013 |   0.000000 |            0 |             0 |
| query end                      | 0.000005 | 0.000006 |   0.000000 |            0 |             0 |
| waiting for handler commit     | 0.000010 | 0.000009 |   0.000000 |            0 |             0 |
| removing tmp table             | 0.000010 | 0.000010 |   0.000000 |            0 |             0 |
| waiting for handler commit     | 0.000005 | 0.000004 |   0.000000 |            0 |             0 |
| closing tables                 | 0.000010 | 0.000010 |   0.000000 |            0 |             0 |
| freeing items                  | 0.000019 | 0.000019 |   0.000000 |            0 |             0 |
| cleaning up                    | 0.000009 | 0.000009 |   0.000000 |            0 |             0 |
+--------------------------------+----------+----------+------------+--------------+---------------+
20 rows in set, 1 warning (0.00 sec)

分析status我们可以知道，这条语句产生了临时表（Creating tmp table），然后最耗时的是executing，在8.0版本中，profile已经把executing，conping to tem table,sorting result sending data 这三个操作同一到了executing里了。在这些操作里，迁移操作（conping to tem table）最费时，但归根结底是因为产生了临时表。
这里列出所有导致sql性能低下的原因，使用profile分析时出现下列任一现象都要注意。

1. converting HEAP to MyISAM查询结果太大，内存都不够用了往磁盘上搬了。
2. Creating tmp table 创建临时表
3. Copying to tmp table on disk 把临时表复制到磁盘（大量IO）
4. locked 锁