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

 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 |
+----------------------+----------+-----------------+---------------+-------------+

 

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值