Bug #117176 The stages about DDL in PFS.events_stages_history_long are wrong
Submitted: 10 Jan 6:20 Modified: 10 Jan 6:58
Reporter: George Ma (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:8.0.40 OS:Any
Assigned to: CPU Architecture:Any
Tags: PFS

[10 Jan 6:20] George Ma
Description:
The table events_stages_history_long in PFS can store all the stages after a statement is executed (https://dev.mysql.com/doc/refman/8.0/en/performance-schema-stage-tables.html).

I have used it to search the execute progress of DDL, and I founded that the stages about DDL are wrong after introduced parallel DDL (WL#14283).

The table structure:

```sql
CREATE TABLE `t1` (
  `id` bigint NOT NULL AUTO_INCREMENT,
  `c1` int DEFAULT NULL,
  `c2` text,
  `c3` int DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_1` (`c1`),
  KEY `idx_3` (`c3`)
) ENGINE=InnoDB;
```

The DDL:

```sql
optimize table t1;
```

The result in MySQL 5.7:

```sql
mysql> select THREAD_ID, EVENT_NAME, TIMER_START, TIMER_END, TIMER_WAIT from performance_schema.events_stages_history_long where EVENT_NAME like "%alter%" order by TIMER_START;
+-----------+------------------------------------------------------+--------------------+--------------------+--------------+
| THREAD_ID | EVENT_NAME                                           | TIMER_START        | TIMER_END          | TIMER_WAIT   |
+-----------+------------------------------------------------------+--------------------+--------------------+--------------+
|        81 | stage/sql/preparing for alter table                  | 251701856368837000 | 251701859868915000 |   3500078000 |
|        81 | stage/sql/altering table                             | 251701859868915000 | 251701859870071000 |      1156000 |
|        81 | stage/innodb/alter table (read PK and internal sort) | 251701859870071000 | 251702150226287000 | 290356216000 |
|        81 | stage/innodb/alter table (merge sort)                | 251702150226287000 | 251702157141860000 |   6915573000 |
|        81 | stage/innodb/alter table (insert)                    | 251702157141860000 | 251702175641217000 |  18499357000 |
|        81 | stage/innodb/alter table (merge sort)                | 251702175641217000 | 251702181858863000 |   6217646000 |
|        81 | stage/innodb/alter table (insert)                    | 251702181858863000 | 251702201963443000 |  20104580000 |
|        81 | stage/innodb/alter table (flush)                     | 251702201963443000 | 251702930840563000 | 728877120000 |
|        81 | stage/innodb/alter table (log apply table)           | 251702930840563000 | 251702930878908000 |     38345000 |
|        81 | stage/sql/committing alter table to storage engine   | 251702930878908000 | 251702930881347000 |      2439000 |
|        81 | stage/innodb/alter table (end)                       | 251702930881347000 | 251702930895480000 |     14133000 |
|        81 | stage/innodb/alter table (log apply table)           | 251702930895480000 | 251703086731347000 | 155835867000 |
+-----------+------------------------------------------------------+--------------------+--------------------+--------------+
12 rows in set (0.00 sec)
```

The result in MySQL 8.0:

```sql
mysql> select THREAD_ID, EVENT_NAME, TIMER_START, TIMER_END, TIMER_WAIT from performance_schema.events_stages_history_long where EVENT_NAME like "%alter%" order by TIMER_START;
+-----------+------------------------------------------------------+------------------+------------------+--------------+
| THREAD_ID | EVENT_NAME                                           | TIMER_START      | TIMER_END        | TIMER_WAIT   |
+-----------+------------------------------------------------------+------------------+------------------+--------------+
|        59 | stage/sql/preparing for alter table                  | 2912076608653000 | 2912114419697000 |  37811044000 |
|        59 | stage/sql/altering table                             | 2912114419697000 | 2912114470811000 |     51114000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912114470811000 | 2912114873229000 |    402418000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912114873229000 | 2912115486035000 |    612806000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912115486035000 | 2912671572611000 | 556086576000 |
|        59 | stage/innodb/alter table (merge sort)                | 2912671572611000 | 2912671824880000 |    252269000 |
|        61 | stage/innodb/alter table (merge sort)                | 2912671588316000 | 2912671847201000 |    258885000 |
|        59 | stage/innodb/alter table (insert)                    | 2912671824880000 | 2912891400387000 | 219575507000 |
|        59 | stage/innodb/alter table (end)                       | 2912891400387000 | 2912891404485000 |      4098000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912891404485000 | 2912891405400000 |       915000 |
|        59 | stage/innodb/alter table (end)                       | 2912891405400000 | 2912891406074000 |       674000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912891406074000 | 2912891406372000 |       298000 |
|        59 | stage/innodb/alter table (merge sort)                | 2912891406372000 | 2912891406657000 |       285000 |
|        59 | stage/innodb/alter table (insert)                    | 2912891406657000 | 2912891407666000 |      1009000 |
|        59 | stage/innodb/alter table (end)                       | 2912891407666000 | 2912891407990000 |       324000 |
|        59 | stage/innodb/alter table (read PK and internal sort) | 2912891407990000 | 2912891408209000 |       219000 |
|        59 | stage/innodb/alter table (merge sort)                | 2912891408209000 | 2912891408426000 |       217000 |
|        59 | stage/innodb/alter table (insert)                    | 2912891408426000 | 2912891666599000 |    258173000 |
|        59 | stage/innodb/alter table (end)                       | 2912891666599000 | 2912891817823000 |    151224000 |
|        59 | stage/innodb/alter table (end)                       | 2912891817823000 | 2912891969724000 |    151901000 |
|        59 | stage/innodb/alter table (end)                       | 2912891969724000 | 2912891977100000 |      7376000 |
|        59 | stage/innodb/alter table (log apply table)           | 2912891977100000 | 2912892125696000 |    148596000 |
|        59 | stage/sql/committing alter table to storage engine   | 2912892125696000 | 2912892128569000 |      2873000 |
|        59 | stage/innodb/alter table (end)                       | 2912892128569000 | 2912892193906000 |     65337000 |
|        59 | stage/innodb/alter table (log apply table)           | 2912892193906000 | 2913057696669000 | 165502763000 |
+-----------+------------------------------------------------------+------------------+------------------+--------------+
25 rows in set (0.00 sec)
```

I can find each stages and the time cost clearly in MySQL 5.7, but it becomes a mess in MySQL 8.0. For example, the stage named 'stage/innodb/alter table (read PK and internal sort)' appears only once in MySQL 5.7, but it appears 6 times in MySQL 8.0. You may say that MySQL 8.0 introduces parallel DDL, and it uses multiple threads to do the DDL, but the THREAD_ID in above result is the same.

And I have searched the code of MySQL 8.0, for optimize table, the parallel_reader will still use the sync mode to do the scan. So, I think the stages about DDL in PFS.events_stages_history_long are wrong.

How to repeat:
No need.
[10 Jan 6:58] MySQL Verification Team
Hello George Ma,

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

regards,
Umesh