为何COUNT很慢却不写SLOW LOG

MySQL对COUNT(*)一直在优化。

1. 问题描述

某日,群友反馈问题对大表COUNT(*)很慢,但却不会记录到slow log中,这是为什么呢?
我自己根据他提供的信息,复现了这个问题:

# MySQL版本是8.0.20
[root@yejr.run]>\s
...
Server version:     8.0.20 MySQL Community Server - GPL
...

# 确认 long_query_time
[root@yejr.run]>select @@global.long_query_time, @@session.long_query_time;
+--------------------------+---------------------------+
| @@global.long_query_time | @@session.long_query_time |
+--------------------------+---------------------------+
|                 0.010000 |                  0.010000 |
+--------------------------+---------------------------+

# 执行 COUNT(*),耗时超过 0.01,但slow log没有记录
[root@yejr.run]>select count(*) from t1;
+----------+
| count(*) |
+----------+
|   799994 |
+----------+
1 row in set (0.27 sec)

这到底是为什么呢?

2. 问题排查

我们先检查所有和slow log相关的参数:

[root@yejr.run]>show global variables;
...
| log_slow_admin_statements              | OFF      |
| log_slow_extra                         | ON       |
| log_slow_slave_statements              | OFF      |
| long_query_time                        | 0.010000 |
| slow_query_log                         | ON       |
| slow_query_log_file                    | slow.log |
| log_output                             | FILE     |
| min_examined_row_limit                 | 100      |
| log_queries_not_using_indexes          | 1        |
| log_throttle_queries_not_using_indexes | 60       |
...

上面几个参数中,比较可疑有下面几个:

| min_examined_row_limit                 | 100      |
| log_queries_not_using_indexes          | 1        |
| log_throttle_queries_not_using_indexes | 60       |

先说 log_queries_not_using_indexes,这表示把没有使用索引的SQL也当成slow query记录下来,但在本例中,是有走索引的:

[root@yejr.run]>desc select count(*) from t1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t1
   partitions: NULL
         type: index
possible_keys: NULL
          key: PRIMARY
      key_len: 4
          ref: NULL
         rows: 42760
     filtered: 100.00
        Extra: Using index

由此也顺便排除了参数 log_throttle_queries_not_using_indexes 的嫌疑。
那么,只剩下参数 min_examined_row_limit 的嫌疑,它表示当扫描行数少于设定值时,这个SQL也不会被当做slow query记录下来。
那么,本例中的COUNT(*)是否符合这种情况呢?
我们先把参数 min_examined_row_limit 值设置为 0,也就是默认值。

[root@yejr.run]>set global min_examined_row_limit=0;
[root@yejr.run]>set session min_examined_row_limit=0;
[root@yejr.run]>select @@global.min_examined_row_limit, @@session.min_examined_row_limit;
+---------------------------------+----------------------------------+
| @@global.min_examined_row_limit | @@session.min_examined_row_limit |
+---------------------------------+----------------------------------+
|                               0 |                                0 |
+---------------------------------+----------------------------------+

再执行一次 COUNT(*) 查询

[root@yejr.run]>select count(*) from t1;
+----------+
| count(*) |
+----------+
|    43462 |
+----------+
1 row in set (0.02 sec)

果然,这次被记录到slow log中了

# Query_time: 0.026083  Lock_time: 0.000110 Rows_sent: 1  Rows_examined: 0
...
select count(*) from t1;

注意到 Rows_examined 的值是 0,嗯,好像不太科学?

到这里,原因查明了,参数 min_examined_row_limit 的值设置大于 0 了,而本例中的 COUNT(*) 操作因为 Rows_examined=0,所以不会被记录到slow log中。

3. 问题解释

虽然知道问题原因了,但 Rows_examined 表示什么意思呢,文档中的解释如下:

• Rows_examined: 
The number of rows examined by the server layer (not counting any processing internal to storage engines).

可能字面意思上看起来不太好理解,换个思路,其实就是我们执行完一个SQL后,查看状态变量中名为 Handler_read_% 的几个指标即可,例如:

[root@yejr.run]> flush status;
[root@yejr.run]> select count(*) from t1;
...
[root@yejr.run]> show status like 'handler%read%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Handler_read_first    | 0     |
| Handler_read_key      | 0     |
| Handler_read_last     | 0     |
| Handler_read_next     | 0     |
| Handler_read_prev     | 0     |
| Handler_read_rnd      | 0     |
| Handler_read_rnd_next | 0     |
+-----------------------+-------+

可以看到以上几个值均为 0,因此 Rows_examined 也为 0,就不会被记录到slow log中了。

3.1 关于聚集索引并行读

说到这里,我还要隆重介绍MySQL 8.0的另一个新特性。
从8.0.14版本起,新增参数 innodb_parallel_read_threads,支持对聚集索引的并行扫描,需要满足以下几个条件:
– 参数 innodb_parallel_read_threads 值 > 0
– 只支持聚集索引
– 只支持无锁查询
– 不是INSERT…SELECT查询

主要用于加速以下两种场景:
– CHECK TABLE操作
– 不带WHERE条件的全表COUNT(*)

因此,COUNT(*)也是可以并行读聚集索引的,从error log中可以看到类似下面的信息:

[Note] [MY-011825] [InnoDB] Parallel scan: 4
[Note] [MY-011825] [InnoDB] ranges: 130 max_threads: 4 split: 128 depth: 1
[Note] [MY-011825] [InnoDB] n: 20914
[Note] [MY-011825] [InnoDB] n: 18066
[Note] [MY-011825] [InnoDB] n: 4482

从上述日志能看出来几点:
1. 设置了最高4个并行线程
2. 实际并行3个线程,实际并行数从1~4,不一定每次都跑最高并行
3. 分别扫描行数是 20914、18066、4482,即 COUNT() 结果总数是 43462

对t1表加上一个辅助索引后,再来看下面这个COUNT(*)

# 看起来这个查询是走辅助索引
[root@yejr.run]>desc select count(*) from t1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t1
   partitions: NULL
         type: index
possible_keys: NULL
          key: k1
      key_len: 5
          ref: NULL
         rows: 42760
     filtered: 100.00
        Extra: Using index

# 实际执行一把
[root@yejr.run]>select count(*) from t1;
+----------+
| count(*) |
+----------+
|    43462 |
+----------+
1 row in set (0.01 sec)

# 发现 Handler_read_% 的值还是 0
[root@yejr.run]>show status like 'handler%read%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Handler_read_first    | 0     |
| Handler_read_key      | 0     |
| Handler_read_last     | 0     |
| Handler_read_next     | 0     |
| Handler_read_prev     | 0     |
| Handler_read_rnd      | 0     |
| Handler_read_rnd_next | 0     |
+-----------------------+-------+        

且此时error log中依然有并行扫描的记录

[Note] [MY-011825] [InnoDB] Parallel scan: 4
[Note] [MY-011825] [InnoDB] ranges: 91 max_threads: 4 split: 88 depth: 1
[Note] [MY-011825] [InnoDB] n: 21493
[Note] [MY-011825] [InnoDB] n: 21486
[Note] [MY-011825] [InnoDB] n: 483

看到了么,实际上还是用到了聚集索引的并行扫描特性来加速。

提醒:上述error log中记录并行扫描聚集索引信息的功能在8.0.20中又被去掉了,上面之所以能看到这段日志是因为我排查到后面又回退到8.0.19版本了,有点费劲。。。
看下8.0.20 Release Notes

InnoDB: Unnecessary messages about parallel scans were printed to the error log. (Bug #30330448)

其实留着不挺好的嘛,搞不懂为毛要去掉的说。。。

提醒:MySQL 5.6版本里,无论基于主键还是辅助索引的全表无WHERE条件的COUNT(*),Rows_examined记录的是总行数,而不是像8.0那样值为0。

延伸阅读

Enjoy MySQL :)

全文完。


扫码加入叶老师的「MySQL核心优化课」,开启MySQL的修行之旅吧。

[MySQL FAQ]系列 — 打开general log到底影响多大

我们知道,有时候为了debug或跟踪方便,会临时打开MySQL的general log。如果在线业务请求比较频繁的话,会导致瞬间产生大量的日志,一定程度上会影响IOPS性能。

此外,我们还有一种变通的办法,那就是打开slow query log,然后设置 long_query_time = 0,这样也可以记录所有请求log,而且记录的log比general log还要来的小,他产生的IOPS性能影响可能会比直接打开general log的影响来的小,可事实果真如此吗?我们来对比测试下就知道了。

测试试用MySQL版本:5.5.5-10.0.11-MariaDB-log MariaDB Server
测试工具: tpcc-mysql
测试Warehouse数: 100
warmup time: 60s
run time: 600s
并发线程数: 512

测试结果对比见下:

mysql-faq-impact-of-general-log

在“一般场景”下,我是设置 long_query_time = 1,并且关闭general log。

记录全部general log时的TpmC大约是不打开log时的73.28%,而记录全部slow log时的TpmC大约是不打开log时的59.53%。可见,直接打开general log对TpmC的影响更小一些,而且这种模式下产生的log其实也更小一些。是不是有点毁三观,哈哈O(∩_∩)O~

此外,如果 log-output = TABLE 时结果会怎样,请读者自行测试 :)

备注:MySQL 5.1及以上版本,才支持将long_query_time设置为0秒,在这之前的版本,其最小值是1秒。

[MySQL FAQ]系列 — slow log中出现大量的binlog dump记录

线上有个数据库,在slow log中,存在大量类似下面的记录:

# Time: 130823 13:56:08
# User@Host: repl[repl] @ slave [10.x.x.x]
# Query_time: 9.000833 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1377237368;
# administrator command: Binlog Dump;

每完成一次binlog dump都会被记录下来,看着非常不爽(我有强迫症,O(∩_∩)O哈哈~),得想着法子搞掉。
经过排查,最后确认是特定版本存在这个现象,目前发现官方 5.1.49 存在,估计整个官方 5.1.x 都会有这个现象。

解决方法:
修改 my.cnf 配置文件,增加或修改下面这个选项:

log-slow-admin-statements = 0

比较坑人的是,这个选项在5.1无法在线修改,需要重启mysqld。
手册上关于这个选项的解释如下:

Include slow administrative statements in the statements written to the slow query log. Administrative statements include ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE.

手册也有不靠谱的时候啊,还是实践出真知。