MySQL Bugs: #112959: Wrong rows examined in P_S and slow log for Index Merge.

Bug #112959	Wrong rows examined in P_S and slow log for Index Merge.
Submitted:	3 Nov 2023 17:53	Modified:	6 Nov 2023 13:55
Reporter:	Jean-François Gagné	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S3 (Non-critical)
Version:	8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Hi,

in the 8.2 release notes [1], I read:

[1]: 

> The SUM_ROWS_EXAMINED column of the Performance Schema events_statements_summary_by_digest table did not provide a correct count of rows for Index Merge. (Bug #35616015)

I did not find a reference to Bug #35616015 in the 8.0.35 release notes [2], so I tested and the results are different from 8.2, see How to repeat for details.  I would expect a bug fixed in 8.2 to also be fixed in 8.0.35.

[2]: https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-35.html

Note that both events_statements_summary_by_digest and the slow log are affected, and fixed in 8.2.

I flagged this as serious, because this impacts the ability of identifying which queries generate load on in MySQL, which is not a minor thing.

Many thanks for looking into this,

Jean-François Gagné

How to repeat:
# Create a 8.0.35 sandbox.
dbdeployer deploy single mysql_8.0.35 -c slow_query_log=ON -c log_output=TABLE -c long_query_time=0

# Create a schema and table, and put data in the table.
./use <<< "
  create database test_jfg;
  create table test_jfg.t(
    id bigint not null auto_increment primary key,
    v1 int not null,
    v2 int not null,
    key(v1), key(v2));
  insert into test_jfg.t (v1,v2) values (1,1),(2,2),(3,3);
"

# Explain, clean env, query and stats.
./use -t <<< "
  explain select count(*) from test_jfg.t where v1 = 1 or v2 = 2\G
  truncate table performance_schema.events_statements_summary_by_digest;
  TRUNCATE mysql.slow_log; 
  flush status;
  select count(*) from test_jfg.t where v1 = 1 or v2 = 2;
  show status like 'Handler_read%';
  select DIGEST_TEXT, SUM_ROWS_EXAMINED from performance_schema.events_statements_summary_by_digest where DIGEST_TEXT like '%test_jfg%';
  SELECT rows_examined, sql_text FROM mysql.slow_log WHERE sql_text LIKE '%%test_jfg%' AND sql_text NOT LIKE '%events%';
"
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t
   partitions: NULL
         type: index_merge
possible_keys: v1,v2
          key: v1,v2
      key_len: 4,4
          ref: NULL
         rows: 2
     filtered: 100.00
        Extra: Using union(v1,v2); Using where
+----------+
| count(*) |
+----------+
|        2 |
+----------+
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Handler_read_first    | 0     |
| Handler_read_key      | 4     |
| Handler_read_last     | 0     |
| Handler_read_next     | 2     |
| Handler_read_prev     | 0     |
| Handler_read_rnd      | 2     |
| Handler_read_rnd_next | 0     |
+-----------------------+-------+
+---------------------------------------------------------------------+-------------------+
| DIGEST_TEXT                                                         | SUM_ROWS_EXAMINED |
+---------------------------------------------------------------------+-------------------+
| SELECT COUNT ( * ) FROM `test_jfg` . `t` WHERE `v1` = ? OR `v2` = ? |                 0 |
+---------------------------------------------------------------------+-------------------+
+---------------+--------------------------------------------------------+
| rows_examined | sql_text                                               |
+---------------+--------------------------------------------------------+
|             0 | select count(*) from test_jfg.t where v1 = 1 or v2 = 2 |
+---------------+--------------------------------------------------------+

# I get the same as above for 8.1.

# But for 8.2, I get this, which makes more sense (2 rows examined instead of 0).
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t
   partitions: NULL
         type: index_merge
possible_keys: v1,v2
          key: v1,v2
      key_len: 4,4
          ref: NULL
         rows: 2
     filtered: 100.00
        Extra: Using union(v1,v2); Using where
+----------+
| count(*) |
+----------+
|        2 |
+----------+
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Handler_read_first    | 0     |
| Handler_read_key      | 4     |
| Handler_read_last     | 0     |
| Handler_read_next     | 2     |
| Handler_read_prev     | 0     |
| Handler_read_rnd      | 2     |
| Handler_read_rnd_next | 0     |
+-----------------------+-------+
+---------------------------------------------------------------------+-------------------+
| DIGEST_TEXT                                                         | SUM_ROWS_EXAMINED |
+---------------------------------------------------------------------+-------------------+
| SELECT COUNT ( * ) FROM `test_jfg` . `t` WHERE `v1` = ? OR `v2` = ? |                 2 |
+---------------------------------------------------------------------+-------------------+
+---------------+--------------------------------------------------------+
| rows_examined | sql_text                                               |
+---------------+--------------------------------------------------------+
|             2 | select count(*) from test_jfg.t where v1 = 1 or v2 = 2 |
+---------------+--------------------------------------------------------+

Salut Monsieur Gagne,

Thank you very much for your bug report.

We have managed to repeat your results:

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

         id: 1
  select_type: SIMPLE
        table: t
   partitions: NULL
         type: index_merge
possible_keys: v1,v2
          key: v1,v2
      key_len: 4,4
          ref: NULL
         rows: 2
     filtered: 100.00
        Extra: Using union(v1,v2); Using where
count(*)
2
Variable_name	Value
Handler_read_first	0
Handler_read_key	4
Handler_read_last	0
Handler_read_next	2
Handler_read_prev	0
Handler_read_rnd	2
Handler_read_rnd_next	0

+---------------------------------------------------------------------+-------------------+
| DIGEST_TEXT                                                         |
SUM_ROWS_EXAMINED |
+---------------------------------------------------------------------+-------------------+
| SELECT COUNT ( * ) FROM `test_jfg` . `t` WHERE `v1` = ? OR `v2` = ? | 
              0 |
+---------------------------------------------------------------------+-------------------+
+---------------+--------------------------------------------------------+
| rows_examined | sql_text                                                                              |                                              
|                                                                                                                        | 
+---------------+--------------------------------------------------------+
|             0 | select count(*) from test_jfg.t where v1 = 1 or v2 = 2                |
|                                                                                                                        |
+---------------+--------------------------------------------------------+

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

Verified as reported.

Affects 8.0, 8.1 and 8.2.

Thanks for verifying my bug MySQL Verification Team.

> Affects 8.0, 8.1 and 8.2.

Unless I am mistaken, 8.2 is not affected.  According to the release notes, it was fixed in Bug #35616015, but it looks like this fix was not back-ported to 8.0.

A few modifications to the report were done which looses information, they are traced below with my comment.

> -Category:         Server
> +Category:         Server: Performance Schema

This also affects the slow log, so it looks like this is a problem a little broader than only Performance Schema.  I also modified the title of the report to represent this, old title was "Wrong SUM_ROWS_EXAMINED in P_S.events_statements_summary for Index Merge", new title is "Wrong rows examined in P_S and slow log for Index Merge".

> -Severity:         S2 (Serious)
> +Severity:         S3 (Non-critical)

As I wrote in my original report, I think this is not a minor bug because "this impacts the ability of identifying which queries generate load on in MySQL, which is not a minor thing".

> -Version:          8.1, 8.0.35
> +Version:          8.0

Unclear why 8.1 was removed, and unclear why 8.0.35 was replaced by 8.0 (does this affect all 8.0 ?).

Thank you for the feedback, Mr. Gagne.

We can set only one category, but your additional comments are also copied to our internal bugs system.