不可“迷信”的row_examined

qq_38972208

已于 2024-09-13 15:49:00 修改

阅读量704

点赞数 4

分类专栏： MySQL 文章标签： mysql

于 2024-09-13 15:47:04 首次发布

本文链接：https://blog.csdn.net/qq_38972208/article/details/142212815

版权

MySQL 专栏收录该内容

1 篇文章

订阅专栏

都是来自生产环境的经验教训哇

前言

row_examined通常是衡量SQL性能的一个指标，在一些场景中不能反映真实的扫描行数易产生误导

row_examined含义：

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

row_examined统计的是server层扫描的行数，不包括引擎层扫描的行数

官方文档：https://dev.mysql.com/doc/refman/8.4/en/slow-query-log.html

在生产中，以下场景不能“迷信” row_examined：

使用到ICP优化
index merge场景
MySQL 8.0 行数统计、子查询row_examined缺陷

另外，存在order by且文件排序的的情况下，slow log中的row_examined会重复计算，参见：https://segmentfault.com/a/1190000022241604

验证

ICP场景

当优化器使用到ICP时，由于ICP是在引擎层过滤掉了一部分数据，这一部分数据并不会统计到row_examined中，正如官方文档中所说不包括引擎层处理

验证：

-- 表结构
mysql> show create table tt\G
*************************** 1. row ***************************
       Table: tt
Create Table: CREATE TABLE `tt` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c1` char(64) NOT NULL,
  `c2` char(64) NOT NULL,
  `c3` char(64) NOT NULL,
  `c4` char(64) NOT NULL,
  `c5` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_test` (`c1`,`c2`,`c3`)
) ENGINE=InnoDB AUTO_INCREMENT=980960 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

-- SQL执行计划
mysql> explain select * from tt where c1='a'  and  c3='aec7c' order by c5;
+----+-------------+-------+------------+------+---------------+----------+---------+-------+--------+----------+---------------------------------------+
| id | select_type | table | partitions | type | possible_keys | key      | key_len | ref   | rows   | filtered | Extra                                 |
+----+-------------+-------+------------+------+---------------+----------+---------+-------+--------+----------+---------------------------------------+
|  1 | SIMPLE      | tt    | NULL       | ref  | idx_test      | idx_test | 256     | const | 381888 |    10.00 | Using index condition; Using filesort |
+----+-------------+-------+------------+------+---------------+----------+---------+-------+--------+----------+---------------------------------------+
1 row in set, 1 warning (0.00 sec)

mysql>  select * from tt where c1='a'  and  c3='aec7c' order by c5;
Empty set (1.69 sec)


-- 相关条件记录数
mysql> select count(*) from tt where c1='a';
+----------+
| count(*) |
+----------+
|   395216 |
+----------+
1 row in set (0.71 sec)

mysql> select count(*) from tt where c1='a' and c3='aec7c';
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.84 sec)


-- 由于使用了ICP，返回给server层的记录数为0，这里显示扫描行数为0 
# Time: 2024-09-11T09:43:09.484724+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   350
# Query_time: 1.681396  Lock_time: 0.000193 Rows_sent: 0  Rows_examined: 0
SET timestamp=1726018989;
select * from tt where c1='a'  and  c3='aec7c' order by c5;

监控ICP的次数

-- 查看
mysql> SELECT name,subsystem,count,status FROM information_schema.innodb_metrics WHERE name LIKE '%icp%';
+------------------+-----------+-------+----------+
| name             | subsystem | count | status   |
+------------------+-----------+-------+----------+
| icp_attempts     | icp       |     0 | disabled |
| icp_no_match     | icp       |     0 | disabled |
| icp_out_of_range | icp       |     0 | disabled |
| icp_match        | icp       |     0 | disabled |
+------------------+-----------+-------+----------+
4 rows in set (0.00 sec)


-- 开启ICP监控

mysql> set global innodb_monitor_enable='icp%';
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT name,subsystem,count,status FROM information_schema.innodb_metrics WHERE name LIKE '%icp%';
+------------------+-----------+-------+---------+
| name             | subsystem | count | status  |
+------------------+-----------+-------+---------+
| icp_attempts     | icp       |     0 | enabled |
| icp_no_match     | icp       |     0 | enabled |
| icp_out_of_range | icp       |     0 | enabled |
| icp_match        | icp       |     0 | enabled |
+------------------+-----------+-------+---------+
4 rows in set (0.01 sec)


-- 再次执行查询
mysql> select * from tt where c1='a'  and  c3='aec7c' order by c5;
Empty set (1.71 sec)


-- 可以看到发生了395217次的ICP，匹配条件的有0次
mysql> SELECT name,subsystem,count,status FROM information_schema.innodb_metrics WHERE name LIKE '%icp%';
+------------------+-----------+--------+---------+
| name             | subsystem | count  | status  |
+------------------+-----------+--------+---------+
| icp_attempts     | icp       | 395217 | enabled |
| icp_no_match     | icp       | 395216 | enabled |
| icp_out_of_range | icp       |      1 | enabled |
| icp_match        | icp       |      0 | enabled |
+------------------+-----------+--------+---------+
4 rows in set (0.00 sec)

索引合并场景

验证SQL

mysql> explain select * from test_merge where c1=1 and c2=5;
+----+-------------+------------+------------+-------------+---------------+---------------+---------+------+------+----------+---------------------------------------------+
| id | select_type | table      | partitions | type        | possible_keys | key           | key_len | ref  | rows | filtered | Extra                                       |
+----+-------------+------------+------------+-------------+---------------+---------------+---------+------+------+----------+---------------------------------------------+
|  1 | SIMPLE      | test_merge | NULL       | index_merge | idx_c1,idx_c2 | idx_c2,idx_c1 | 5,5     | NULL | 3071 |   100.00 | Using intersect(idx_c2,idx_c1); Using where |
+----+-------------+------------+------------+-------------+---------------+---------------+---------+------+------+----------+---------------------------------------------+
1 row in set, 1 warning (0.00 sec)

相关条件数据量：


mysql> select count(*) from test_merge where c1=1;
+----------+
| count(*) |
+----------+
|    53248 |
+----------+
1 row in set (0.02 sec)

mysql> select count(*) from test_merge where  c2=5;
+----------+
| count(*) |
+----------+
|     6144 |
+----------+
1 row in set (0.00 sec)


mysql> select count(*) from test_merge where c1=1 and c2=5;
+----------+
| count(*) |
+----------+
|     4096 |
+----------+
1 row in set (0.04 sec)

慢日志记录：显示扫描行数为4096

# Time: 2024-09-11T17:46:57.031698+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   369
# Query_time: 0.091583  Lock_time: 0.000195 Rows_sent: 4096  Rows_examined: 4096
SET timestamp=1726048017;
select * from test_merge where c1=1 and c2=5;

通过performance_schema.table_io_waits_summary_by_index_usage监控

mysql> truncate table performance_schema.table_io_waits_summary_by_index_usage;
Query OK, 0 rows affected (0.00 sec)

mysql>  select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,COUNT_STAR,COUNT_READ,COUNT_WRITE,COUNT_FETCH,COUNT_INSERT,COUNT_UPDATE,COUNT_DELETE  from performance_schema.table_io_waits_summary_by_index_usage where object_schema='test'and object_name='test_merge';
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | COUNT_STAR | COUNT_READ | COUNT_WRITE | COUNT_FETCH | COUNT_INSERT | COUNT_UPDATE | COUNT_DELETE |
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
| TABLE       | test          | test_merge  | PRIMARY    |          0 |          0 |           0 |           0 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | idx_c1     |          0 |          0 |           0 |           0 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | idx_c2     |          0 |          0 |           0 |           0 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | NULL       |          0 |          0 |           0 |           0 |            0 |            0 |            0 |
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
4 rows in set (0.01 sec)

mysql> select * from test_merge where c1=1 and c2=5 ;
...
+--------+------+------+------+
4096 rows in set (0.06 sec)

mysql>  select OBJECT_TYPE,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,COUNT_STAR,COUNT_READ,COUNT_WRITE,COUNT_FETCH,COUNT_INSERT,COUNT_UPDATE,COUNT_DELETE  from performance_schema.table_io_waits_summary_by_index_usage where object_schema='test'and object_name='test_merge';
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | COUNT_STAR | COUNT_READ | COUNT_WRITE | COUNT_FETCH | COUNT_INSERT | COUNT_UPDATE | COUNT_DELETE |
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
| TABLE       | test          | test_merge  | PRIMARY    |          0 |          0 |           0 |           0 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | idx_c1     |      53237 |      53237 |           0 |       53237 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | idx_c2     |       6145 |       6145 |           0 |        6145 |            0 |            0 |            0 |
| TABLE       | test          | test_merge  | NULL       |       4096 |       4096 |           0 |        4096 |            0 |            0 |            0 |
+-------------+---------------+-------------+------------+------------+------------+-------------+-------------+--------------+--------------+--------------+
4 rows in set (0.01 sec)

看上去索引合并扫描的记录数没有计算，而仅计算通过索引合并取交集回表后返回给server层的记录数

向官方提交一个bug:https://bugs.mysql.com/bug.php?id=116058

8.0版本row_examined bug

行数统计+无where条件、子查询扫描行数不准确
bug链接：https://bugs.mysql.com/bug.php?id=107352

验证：

-- 表行数
mysql> select count(*) from tt;
+----------+
| count(*) |
+----------+
|   786432 |
+----------+
1 row in set (0.16 sec)


-- 8.0版本

# Time: 2024-09-11T05:56:18.702333Z
# User@Host: root[root] @ xxx [xxx]  Id:  2425
# Query_time: 0.162342  Lock_time: 0.000005 Rows_sent: 1  Rows_examined: 0 Execution_time: 0.162337
SET timestamp=1726034178;
select count(*) from tt;

-- 有where条件的count查询是对的
# Time: 2024-09-11T05:57:01.883765Z
# User@Host: root[root] @ xxx [xxx]  Id:  2425
# Query_time: 0.007885  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 7966 Execution_time: 0.007882
SET timestamp=1726034221;
select count(*) from tt where id<10000;


# Time: 2024-09-11T02:47:49.094978Z
# User@Host: root[root] @ xxx [xxx]  Id:  2423
# Query_time: 16.053973  Lock_time: 0.000005 Rows_sent: 5  Rows_examined: 5 Execution_time: 16.053968
use test;
SET timestamp=1726022853;
select * from ((select * from tt order by id desc) union select * from tt ) t limit 5;

# Time: 2024-09-11T05:58:38.617579Z
# User@Host: root[root] @ xxx [xxx]  Id:  2425
# Query_time: 1.410755  Lock_time: 0.000005 Rows_sent: 5  Rows_examined: 5 Execution_time: 1.410750
SET timestamp=1726034317;
select * from ((select * from tt where id<100000 order by id desc) union select * from tt where id<100000 ) t limit 5;



-- 5.7版本正确
# Time: 2024-09-11T11:08:12.078660+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   353
# Query_time: 53.095986  Lock_time: 0.001613 Rows_sent: 5  Rows_examined: 2335301
use zld;
SET timestamp=1726024092;
select * from ((select * from tt order by id desc) union select * from tt ) t limit 5;


# Time: 2024-09-11T11:10:39.379594+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   353
# Query_time: 0.259323  Lock_time: 0.000143 Rows_sent: 1  Rows_examined: 778432
SET timestamp=1726024239;
select count(*) from tt;

order by场景重复计算

验证语句：

select * from test_merge where c1=9 ;
select * from test_merge where c1=9 order by c3 ;

两个sql在慢日志中的记录如下：

# Time: 2024-09-13T14:06:20.402286+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   372
# Query_time: 0.006185  Lock_time: 0.000175 Rows_sent: 2048  Rows_examined: 2048
SET timestamp=1726207580;
select * from test_merge where c1=9;


# Time: 2024-09-13T14:06:23.131253+08:00
# User@Host: root[root] @ xxx [xxx]  Id:   372
# Query_time: 0.008835  Lock_time: 0.000167 Rows_sent: 2048  Rows_examined: 4096
SET timestamp=1726207583;
select * from test_merge where c1=9 order by c3;