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: | |
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
[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.