为何COUNT很慢却不写SLOW LOG

老叶茶馆

发布于 2020-06-23 17:27:18

1.6K0

发布于 2020-06-23 17:27:18

文章被收录于专栏：MySQL修行 | 老叶茶馆MySQL修行 | 老叶茶馆

1. 问题描述2. 问题排查3. 问题解释3.1 关于聚集索引并行读延伸阅读

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

从上述日志能看出来几点：

设置了最高4个并行线程
实际并行3个线程，实际并行数从1~4，不一定每次都跑最高并行
分别扫描行数是 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)

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