Bug #107352 ROWS_EXAMINED confusing in MySQL 8
Submitted: 20 May 11:00 Modified: 30 May 8:21
Reporter: Iwo P Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:8.0.28, 8.0.29 OS:Any
Assigned to: CPU Architecture:Any

[20 May 11:00] Iwo P
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.
[30 May 8:21] MySQL Verification Team
Hello Iwo P,

Thank you for the report and feedback.
Verified as described.

regards,
Umesh