Bug #109034 Slow log Rows_examined value is inaccurate
Submitted: 9 Nov 2022 4:15 Modified: 14 Nov 2022 13:07
Reporter: peng gao Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S4 (Feature request)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[9 Nov 2022 4:15] peng gao
Description:
Hi:
  If query have subquery with group by , use MaterializeIterator to Materialize subquery Query Block,slow log Rows_examined value is inaccurate,
  only contains the top layer Query Block's Rows_examined. Like this:
  
  
mysql> show create table myt1;
+-------+------------------------------------------------------------------------------------+
| Table | Create Table                                                                       |
+-------+------------------------------------------------------------------------------------+
| myt1  | CREATE TABLE `myt1` (
  `id` int DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-------+------------------------------------------------------------------------------------+
1 row in set (0.01 sec)

mysql> set persist long_query_time=0.1;

mysql> insert into myt1 values(10);
...

mysql> insert into myt1 select *from myt1;
Query OK, 1048576 rows affected (6.78 sec)

mysql> select id,count(*) from myt1 group by id  ;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.15 sec)

mysql> select * from (select id,count(*) from myt1 group by id) a;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.09 sec)

slow log:

# Time: 2022-11-09T03:37:19.466846Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.144293  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 2097152
SET timestamp=1667965038;
select id,count(*) from myt1 group by id;
# Time: 2022-11-09T03:37:32.895778Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.091765  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 1
SET timestamp=1667965051;
select * from (select id,count(*) from myt1 group by id) a;

  {  
    auto join_cleanup = create_scope_guard([this, thd] { //slow log examined_rows
      for (SELECT_LEX *sl = first_select(); sl; sl = sl->next_select()) {
        JOIN *join = sl->join;
        join->join_free();
        thd->inc_examined_row_count(join->examined_rows); 
      }
      if (fake_select_lex != nullptr) {
        thd->inc_examined_row_count(fake_select_lex->join->examined_rows);
      }
    });  

here debug:

(gdb) p slave->next
$15 = (SELECT_LEX *) 0x0
(gdb) p slave->slave->slave->join->examined_rows
$24 = 16384
(gdb) p slave->join->examined_rows
$25 = 1

Because this query SELECT_LEX next SELECT_LEX is nullptr, But SELECT_LEX slave SELECT_LEX_UNIT slave SELECT_LEX is subquery query block , examined_rows is correct.

How to repeat:
as Description
[9 Nov 2022 7:06] peng gao
Sorry not subquery ,is DERIVED table.
[9 Nov 2022 12:52] MySQL Verification Team
Hi Mr. gao,

Thank you for your bug report.

However, your report is not complete. You have not provided the full test case, as we are missing many rows.

Next, why would this nested query in the FROM clause be materialised, when it is so easily optimised away, in a manner that it resolves into a straight query without any nested queries !!!!!

Next, what makes you think that materialisation would improve the performance ????? Can you show us with the benchmarks of how faster would that execution be ????

We are waiting on the answers for all of our questions .....
[10 Nov 2022 1:10] peng gao
mysql> show create table myt1;
+-------+------------------------------------------------------------------------------------+
| Table | Create Table                                                                       |
+-------+------------------------------------------------------------------------------------+
| myt1  | CREATE TABLE `myt1` (
  `id` int DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-------+------------------------------------------------------------------------------------+
1 row in set (0.01 sec)

mysql> set persist long_query_time=0.1;

mysql> insert into myt1 values(10);
...

mysql> insert into myt1 select *from myt1;
Query OK, 1048576 rows affected (6.78 sec)

mysql> select id,count(*) from myt1 group by id  ;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.15 sec)

mysql> select * from (select id,count(*) from myt1 group by id) a;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.09 sec)

slow log:

# Time: 2022-11-09T03:37:19.466846Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.144293  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 2097152
SET timestamp=1667965038;
select id,count(*) from myt1 group by id;
# Time: 2022-11-09T03:37:32.895778Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.091765  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 1
SET timestamp=1667965051;
[10 Nov 2022 1:21] peng gao
slow log:

# Time: 2022-11-09T03:37:19.466846Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.144293  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 2097152
SET timestamp=1667965038;
select id,count(*) from myt1 group by id;
# Time: 2022-11-09T03:37:32.895778Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.091765  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 1
SET timestamp=1667965051;
select * from (select id,count(*) from myt1 group by id) a;
[10 Nov 2022 13:47] MySQL Verification Team
Hi Mr. gao,

Rows_examined is correct, since you inserted only one row.

We do not see any more INSERT then for one row only.
[11 Nov 2022 1:38] peng gao
Sorry.

how to repeat detail ,

mysql> show create table myt1;
+-------+------------------------------------------------------------------------------------+
| Table | Create Table                                                                       |
+-------+------------------------------------------------------------------------------------+
| myt1  | CREATE TABLE `myt1` (
  `id` int DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-------+------------------------------------------------------------------------------------+
1 row in set (0.01 sec)

mysql> set persist long_query_time=0.1;

insert into myt1 values(10);
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
insert into myt1 select *from myt1;
Query OK, 1048576 rows affected (6.78 sec)

mysql> select count(*) from myt1;
+----------+
| count(*) |
+----------+
|  2097152 |
+----------+
1 row in set (0.08 sec)

mysql> select id,count(*) from myt1 group by id  ;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.15 sec)

mysql> select * from (select id,count(*) from myt1 group by id) a;
+------+----------+
| id   | count(*) |
+------+----------+
|   10 |  2097152 |
+------+----------+
1 row in set (1.09 sec)

slow log:

# Time: 2022-11-09T03:37:19.466846Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.144293  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 2097152
SET timestamp=1667965038;
select id,count(*) from myt1 group by id;

# Time: 2022-11-09T03:37:32.895778Z
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 1.091765  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 1 (here Rows_examined value is inaccurate)
SET timestamp=1667965051;
select * from (select id,count(*) from myt1 group by id) a;
[11 Nov 2022 1:38] peng gao
But 5.7 slow log is Rows_examined value is correct.

# Time: 2022-11-11T09:36:52.603581+08:00
# User@Host: root[root] @ localhost []  Id:     3
# Query_time: 0.760749  Lock_time: 0.000093 Rows_sent: 1  Rows_examined: 2097154
SET timestamp=1668130612;
select id,count(*) from myt1 group by id;

# Time: 2022-11-11T09:36:58.062363+08:00
# User@Host: root[root] @ localhost []  Id:     3
# Query_time: 0.820477  Lock_time: 0.000102 Rows_sent: 1  Rows_examined: 2097155 (here Rows_examined value is correct)
SET timestamp=1668130618;
select * from (select id,count(*) from myt1 group by id) a;

Thanks
[11 Nov 2022 13:30] MySQL Verification Team
Hi Mr. gao,

I could not reproduce your results.

I have got the following ones:

------------------------------------

select id,count(*) from myt1 group by id;
# Time: 2022-11-11T13:26:02.138478Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 1.330887  Lock_time: 0.000012 Rows_sent: 1  Rows_examined: 1
SET timestamp=1668173160;
select * from (select id,count(*) from myt1 group by id) a;
# Time: 2022-11-11T13:26:06.856227Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.121277  Lock_time: 0.000123 Rows_sent: 0  Rows_examined: 0

-----------------------------------------

These ones do not look quite correct, but this would be truly a minor bug.
[12 Nov 2022 3:11] peng gao
Hi 

Table myt1 has 2097152 rows and no indexes , two select statement need got  2097152 rows from innodb to mysql, so all rows should Calculated to Rows_examined.

In your result,

# Time: 2022-11-11T13:26:02.138478Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 1.330887  Lock_time: 0.000012 Rows_sent: 1  Rows_examined: 1
SET timestamp=1668173160;
select * from (select id,count(*) from myt1 group by id) a;

statement select * from (select id,count(*) from myt1 group by id) a;
only have Rows_examined 1 , Query_time is 1.330887 sec, more 1 sec only scan 1 rows ?  It must be wrong.

please recheck slow log , slow log format statistics first, then statements.
your reslust is statements first then statistics.

Finally, you can use mysql 5.7 to test two statement and check slow log result.

Best Regards .
[12 Nov 2022 3:27] peng gao
Yes,this is a minor bug.
But,slow log very important,sometime,this is only way to trace historical information and Rows_examined to measure statement performance.
Thanks
[14 Nov 2022 13:07] MySQL Verification Team
Hi,

We have repeated your results , so this is now a verified bug of the low priority.