Description:
Rows_examined, regardless if checked via performance_schema or slow query logs, has confusing values. It looks that only rows examined from an outer query are counted.
How to repeat:
Let's consider the below table:
CREATE TABLE `e` (
`id` int NOT NULL AUTO_INCREMENT,
`a` varchar(255) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `z` (`a`)
and queries:
(01) select count(0) from e;
(02) select * from ( (select * from e order by id desc) UNION select * from e ) t limit 5;
(03) select * from ( (select * from e order by id desc) UNION select * from e ) t limit 1;
In MySQL 8.0 the following values are logged:
(01)
# User@Host: msandbox[msandbox] @ localhost [] Id: 17
# Query_time: 0.331050 Lock_time: 0.000002 Rows_sent: 1 Rows_examined: 0 Thread_id: 17 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 62 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2022-05-20T10:50:08.486460Z End: 2022-05-20T10:50:08.817510Z
SET timestamp=1653043808;
select count(0) from e;
---
mysql> flush status; select count(0) from e; show status like 'handler%';
Query OK, 0 rows affected (0,01 sec)
+----------+
| count(0) |
+----------+
| 8388608 |
+----------+
1 row in set (0,35 sec)
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 2 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| 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 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 0 |
+----------------------------+-------+
18 rows in set (0,00 sec)
(02)
# Time: 2022-05-20T10:50:46.161876Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 17
# Query_time: 34.150119 Lock_time: 0.000005 Rows_sent: 5 Rows_examined: 5 Thread_id: 17 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 206 Read_first: 3 Read_last: 0 Read_key: 3 Read_next: 16777216 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 98262 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 1 Created_tmp_tables: 2 Start: 2022-05-20T10:50:12.011757Z End: 2022-05-20T10:50:46.161876Z
SET timestamp=1653043812;
select * from ( (select * from e order by id desc) UNION select * from e ) t limit 5;
---
mysql> flush status; select * from ( (select * from e order by id desc) UNION select * from e ) t limit 5; show status like 'handler%';
Query OK, 0 rows affected (0,01 sec)
+----+---------------------+
| id | a |
+----+---------------------+
| 1 | 2022-05-12 14:59:25 |
| 2 | 2022-05-12 14:59:25 |
| 3 | 2022-05-12 14:59:25 |
| 4 | 2022-05-12 14:59:25 |
| 6 | 2022-05-12 14:59:25 |
+----+---------------------+
5 rows in set (35,24 sec)
+----------------------------+----------+
| Variable_name | Value |
+----------------------------+----------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 4 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 3 |
| Handler_read_key | 3 |
| Handler_read_last | 0 |
| Handler_read_next | 16777216 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 98262 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 16875473 |
+----------------------------+----------+
18 rows in set (0,01 sec)
(03)
# Time: 2022-05-20T10:51:24.372249Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 17
# Query_time: 32.981762 Lock_time: 0.000004 Rows_sent: 1 Rows_examined: 1 Thread_id: 17 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 102 Read_first: 3 Read_last: 0 Read_key: 3 Read_next: 16777216 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 98258 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 1 Created_tmp_tables: 2 Start: 2022-05-20T10:50:51.390487Z End: 2022-05-20T10:51:24.372249Z
SET timestamp=1653043851;
select * from ( (select * from e order by id desc) UNION select * from e ) t limit 1;
---
mysql> flush status; select * from ( (select * from e order by id desc) UNION select * from e ) t limit 1; show status like 'handler%';
Query OK, 0 rows affected (0,01 sec)
+----+---------------------+
| id | a |
+----+---------------------+
| 1 | 2022-05-12 14:59:25 |
+----+---------------------+
1 row in set (33,84 sec)
+----------------------------+----------+
| Variable_name | Value |
+----------------------------+----------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 4 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 3 |
| Handler_read_key | 3 |
| Handler_read_last | 0 |
| Handler_read_next | 16777216 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 98258 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 16875473 |
+----------------------------+----------+
18 rows in set (0,00 sec)
In MySQL 5.7 rows_examined values are different:
(01)
# Time: 2022-05-20T10:55:32.879968Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 10
# Schema: test Last_errno: 0 Killed: 0
# Query_time: 2.470438 Lock_time: 0.000069 Rows_sent: 1 Rows_examined: 8388608 Rows_affected: 0 Bytes_sent: 62
SET timestamp=1653044132;
select count(0) from e;
---
mysql> flush status; select count(0) from e; show status like 'handler%';
Query OK, 0 rows affected (0,00 sec)
+----------+
| count(0) |
+----------+
| 8388608 |
+----------+
1 row in set (2,47 sec)
+----------------------------+---------+
| Variable_name | Value |
+----------------------------+---------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 2 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 1 |
| Handler_read_key | 1 |
| Handler_read_last | 0 |
| Handler_read_next | 8388608 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 0 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 0 |
+----------------------------+---------+
18 rows in set (0,01 sec)
(02)
# Time: 2022-05-20T10:56:54.381327Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 10
# Schema: test Last_errno: 0 Killed: 0
# Query_time: 28.754692 Lock_time: 0.000138 Rows_sent: 5 Rows_examined: 25165829 Rows_affected: 0 Bytes_sent: 206
SET timestamp=1653044214;
select * from ( (select * from e order by id desc) UNION select * from e ) t limit 5;
---
mysql> flush status; select * from ( (select * from e order by id desc) UNION select * from e ) t limit 5; show status like 'handler%';
Query OK, 0 rows affected (0,00 sec)
+----+---------------------+
| id | a |
+----+---------------------+
| 1 | 2022-05-12 14:59:25 |
| 2 | 2022-05-12 14:59:25 |
| 3 | 2022-05-12 14:59:25 |
| 4 | 2022-05-12 14:59:25 |
| 6 | 2022-05-12 14:59:25 |
+----+---------------------+
5 rows in set (28,76 sec)
+----------------------------+----------+
| Variable_name | Value |
+----------------------------+----------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 4 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 4 |
| Handler_read_key | 4 |
| Handler_read_last | 0 |
| Handler_read_next | 16777216 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 8509349 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 120735 |
+----------------------------+----------+
18 rows in set (0,00 sec)
(03)
# Time: 2022-05-20T10:58:03.908399Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 10
# Schema: test Last_errno: 0 Killed: 0
# Query_time: 31.044815 Lock_time: 0.000176 Rows_sent: 1 Rows_examined: 25165825 Rows_affected: 0 Bytes_sent: 102
SET timestamp=1653044283;
select * from ( (select * from e order by id desc) UNION select * from e ) t limit 1;
---
mysql> flush status; select * from ( (select * from e order by id desc) UNION select * from e ) t limit 1; show status like 'handler%';
+----+---------------------+
| id | a |
+----+---------------------+
| 1 | 2022-05-12 14:59:25 |
+----+---------------------+
1 row in set (31,04 sec)
+----------------------------+----------+
| Variable_name | Value |
+----------------------------+----------+
| Handler_commit | 1 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 4 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 4 |
| Handler_read_key | 4 |
| Handler_read_last | 0 |
| Handler_read_next | 16777216 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 8509345 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 120735 |
+----------------------------+----------+
18 rows in set (0,00 sec)
Suggested fix:
The rows examined in 8.0 should include rows examined in all phases of the query, as in 5.7.
