MySql数据库中SQL优化第三篇：通过show profile 分析SQL

最新推荐文章于 2024-08-12 10:15:00 发布

taojin12

最新推荐文章于 2024-08-12 10:15:00 发布

阅读量1.5k

点赞数 1

文章标签： SQ

本文链接：https://blog.csdn.net/taojin12/article/details/81349112

版权

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: 0

mysql> 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 | <unknown>       | sql_parse.cc  |        4745 |
| Opening tables       | 0.000026 | <unknown>       | sql_base.cc   |        4836 |
| System lock          | 0.000014 | <unknown>       | lock.cc       |         299 |
| init                 | 0.000015 | <unknown>       | sql_select.cc |        2554 |
| optimizing           | 0.000007 | <unknown>       | sql_select.cc |         863 |
| executing            | 0.000017 | <unknown>       | sql_select.cc |        1823 |
| end                  | 0.000005 | <unknown>       | sql_select.cc |        2590 |
| query end            | 0.000003 | <unknown>       | sql_parse.cc  |        4434 |
| closing tables       | 0.000007 | <unknown>       | sql_parse.cc  |        4486 |
| freeing items        | 0.000039 | <unknown>       | sql_parse.cc  |        5634 |
| logging slow query   | 0.000002 | <unknown>       | sql_parse.cc  |        1460 |
| cleaning up          | 0.000002 | <unknown>       | sql_parse.cc  |        1416 |
+----------------------+----------+-----------------+---------------+-------------+