Bug #94925 Wrong Query Sample Text in Performance Query
Submitted: 6 Apr 2019 0:15 Modified: 24 Apr 2019 13:22
Reporter: Peter Zaitsev Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:8.0.15 OS:Any
Assigned to: CPU Architecture:Any

[6 Apr 2019 0:15] Peter Zaitsev
Description:
Running sysbench tpcc test I noticed sometimes  QUERY_SAMPLE_TEXT is way off compared to the real query 

*************************** 1. row ***************************
                SCHEMA_NAME: tpcc
                     DIGEST: e60aef21fcdd1f23c8bc9b9f5002614d0aeb5c0b7c5bc12618209f0726b16a46
                DIGEST_TEXT: SELECT `cat` . `name` AS `TABLE_CATALOG` , `sch` . `name` AS `TABLE_SCHEMA` , `tbl` . `name` AS `TABLE_NAME` , `tbl` . `type` AS `TABLE_TYPE` , IF ( ( `tbl` . `type` = ? ) , `tbl` . `engine` , ? ) AS `ENGINE` , IF ( ( `tbl` . `type` = ? ) , ?, ... ) AS `VERSION` , `tbl` . `row_format` AS `ROW_FORMAT` , `internal_table_rows` ( `sch` . `name` , `tbl` . `name` , IF ( `isnull` ( `tbl` . `partition_type` ) , `tbl` . `engine` , ? ) , `tbl` . `se_private_id` , ( `tbl` . `hidden` != ? ) , `ts` . `se_private_data` , COALESCE ( `stat` . `table_rows` , ? ) , COALESCE ( CAST ( `stat` . `cached_time` AS UNSIGNED ) , ? ) ) AS `TABLE_ROWS` , `internal_avg_row_length` ( `sch` . `name` , `tbl` . `name` , IF ( `isnull` ( `tbl` . `partition_type` ) , `tbl` . `engine` , ? ) , `tbl` . `se_private_id` , ( `tbl` . `hidden` != ? ) , `ts` . `se_private_data` , COALESCE ( `stat` . `avg_row_length` , ? ) , COALESCE ( CAST ( `stat` . `cached_time` AS UNSIGNED ) , ? ) ) AS `AVG_ROW_LENGTH` , `internal_data_length` ( `sch` . `name` , `tbl` .
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 2673236000
             MIN_TIMER_WAIT: 2673236000
             AVG_TIMER_WAIT: 2673236000
             MAX_TIMER_WAIT: 2673236000
              SUM_LOCK_TIME: 895000000
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 90
          SUM_ROWS_EXAMINED: 452
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 1
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 1
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 90
              SUM_SORT_SCAN: 1
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
                 FIRST_SEEN: 2019-04-05 23:14:01.012378
                  LAST_SEEN: 2019-04-05 23:14:01.012378
                QUANTILE_95: 2754228703
                QUANTILE_99: 2754228703
               QUANTILE_999: 2754228703
          QUERY_SAMPLE_TEXT: SHOW /*!50002 FULL*/ TABLES
          QUERY_SAMPLE_SEEN: 2019-04-05 23:14:01.012378
    QUERY_SAMPLE_TIMER_WAIT: 2673236000

Note - it is "SHOW FULL TABLES" 

How to repeat:
See above
[9 Apr 2019 12:55] MySQL Verification Team
Hi Peter,

We are happy to hear from you. 

Thank you for your bug report, but we still need some clarifications on what is the problem that you are reporting.

First of all, which query is slow, the one in DIGEST_TEXT or in QUERY_SAMPLE_TEXT. Next question is about unit in which all those *_TIMER_WAIT numbers are expressed. I guess that those are not seconds .....

Last, but not least, can we repeat it somehow, without running the full TPCC test. If entire test has to be run, can you let us know exactly how did you run it ????

Also, it seems that it is MDL locks that waiting happened. It would be beneficial to know the concurrent DML or DDL statements that run and the list of the MDL locks from P_S at that moment ...

Many thanks in advance .....
[9 Apr 2019 12:57] Peter Zaitsev
Hi Sinisa, 

There is no query which is "slow"  I'm just saying what  the sample reported is incorrect for the actual query digest. 

I do not have specific repeatable test case
[9 Apr 2019 13:35] MySQL Verification Team
Hi Peter,

Well, if there are DML statements running in parallel, then yes, SHOW FULL TABLES can wait in some rare situations.

If you think that this is not documented in sufficient detail, we can try to improve upon that. Let us know what would you like us to do exactly.
[17 Apr 2019 3:36] Peter Zaitsev
Sinisa,

I'm puzzled.  I thought what QUERY_SAMPLE_TEXT  is an Example of the query which is in "DIGEST TEXT"   so I do not understand how SHOW TABLE STATUS can be example of SELECT digest
[23 Apr 2019 14:24] MySQL Verification Team
Peter,

It does not seem to be just as an example.

If you think that this needs clarification, let us know and I will proceed in correcting it.

I would also like to know how to repeat your output.
[23 Apr 2019 15:36] Peter Zaitsev
Sinisa,

What do you think it should be when than the query from which digest was computed ?

Per manual 
https://dev.mysql.com/doc/refman/8.0/en/performance-schema-statement-digests.html

Some Performance Tables have a column that stores original SQL statements from which digests are computed:

The SQL_TEXT column of the events_statements_current, events_statements_history, and events_statements_history_long statement event tables.

The QUERY_SAMPLE_TEXT column of the events_statements_summary_by_digest summary table.

It shows what this query should have the one of the query from which digest was computed, no ?
[24 Apr 2019 10:33] Dennis Sehalic
There seems to be some confusion here, what Peter is saying is that the normalized query in DIGEST_TEXT and the samtple query text in QUERY_SAMPLE_TEXT is not matching. Take a look at this example, also in a 8.0.15 instance:

mysql> select DIGEST_TEXT,QUERY_SAMPLE_TEXT from performance_schema.events_statements_summary_by_digest where DIGEST='335d32260760bd4266a9a2c0487200e8aeb704ef9272ae5f55b5bd2f03a3e5ad'\G
*************************** 1. row ***************************
      DIGEST_TEXT: SELECT ? AS `1` , ? AS `0` , ? AS `1`
QUERY_SAMPLE_TEXT: SELECT * FROM mysql_innodb_cluster_metadata.schema_version

For this particular query QUERY_SAMPLE_TEXT is actually correct, but the normalizing funtion that creates the value in DIGEST_TEXT is just wrong.
[24 Apr 2019 10:35] Dennis Sehalic
Edit, not plain wrong, but not really matching hehe
[24 Apr 2019 13:22] MySQL Verification Team
Hi Peter,

Yes you are correct. This is a minor bug in the P_S.

Verified as reported.