slow test TestIndexMergeUpgradeFrom400To540Enable|Disable in session pkg

[wuhuizuo]

Bug Report

Average timecost was 294480.0000ms between "2023-09-01" AND "2023-09-08"

Found records: 1 (filter only for runs that timecost >= threshold)
Max timecost: 294480ms
Min timecost: 294480ms
Avg timecost: 294480.0000ms

• CI build: used 294480ms

[Defined2014]

Seems it's slow at Bootstrap, the time cost for ddl related SQLs cosume lot of time, like

# Txn_start_ts: 444045546125524992
# Query_time: 3.168740064
# Parse_time: 0
# Compile_time: 0.028482433
# Rewrite_time: 0.004461022
# Optimize_time: 0.020721031
# Wait_TS: 0.000208758
# Cop_time: 3.109948172 Process_time: 0.002 Request_count: 2
# Is_internal: true
# Digest: a5ae371f91ff344239c371574cfd61b79aa3a5899858f81f0a16e0e20d2730bc
# Stats: tidb_ddl_job:pseudo[10000;0]
# Num_cop_tasks: 2
# Cop_proc_avg: 0.001 Cop_proc_p90: 0.002 Cop_proc_max: 0.002 Cop_proc_addr: store1
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: store1
# Mem_max: 12637
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 0
# PD_total: 0
# Backoff_total: 0
# Write_sql_response_total: 0
# Result_rows: 0
# Succ: true
# IsExplicitTxn: false
# IsSyncStatsFailed: false
# Plan: tidb_decode_plan('jRS4MAkzXzEzCTAJMjIyMy41NQlteXNxbC50aWRiX2RkbF9qb2Iuam9iX21ldGEsIG1GHQDwQ3Byb2Nlc3NpbmcJMAl0aW1lOjMuMTNzLCBsb29wczoxLCBDb25jdXJyZW5jeTo1CTExLjggS0IJTi9BCjEJMTRfMTQJcn4AGWEUOmRlc2MsToUAFGpvYl9pZFaBABwJMCBCeXRlcxEIHAoyCTE3XzI4HfRUaW5uZXIgam9pbiwgZXF1YWw6W2VxKFoKAQRpZAHTIGx1bW4jMTUpXVZ1AJgsIGJ1aWxkX2hhc2hfdGFibGU6e3RvdGFsOjEuNDJtcywgZmV0Y2gVDgUuDDowc30RphEIJAozCTMxXzQxKEIBUAApHbVAZGF0YTpTZWxlY3Rpb25fNDARihg2NjQuMcK1LoMBcGNvcF90YXNrOiB7bnVtOiAxLCBtYXg6IDg4Ni40BSshZjRfa2V5czogMCwgcnBjXxEpAQwl2BQgNzg3LjcFLmRjb3ByX2NhY2hlX2hpdF9yYXRpbzogMC4wMBH5AW4IX2R1BRoQbjogNjANaDhtYXhfZGlzdHNxbF9jb25VGRggMX0JMTc5LasYTi9BCjQJMQHVCDFfMG6cAgxyZW9ySXoEa3YFdQQ6ewWtCDYzMQ2sSYgEMH0BVQEEHAo1CTQ0XzM5BVocNjY2Ni42Nwkpoy72AugsIHJhbmdlOlstaW5mLDcpLCAoNywraW5mXSwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCWEIoo4ALDMJNl8yOShQcm9iZSHfODY0MDAJZ3JvdXAgYnk6Q1FpQCwgZnVuY3M6Zmlyc3Ryb3coFRoIKS0+FQxRAz6DA0xwYXJ0aWFsX3dvcmtlcjp7d2FsbCnVNDMuMTI1NTU1MjUxcywgLpIBCDUsICXFQQhgMCwgdG90X3dhaXQ6MTUuNjIyMDc4MzE5cwkYFGV4ZWM6MA0NJX8JJRgxNjE3MjJzSW0BahQ0NDgxODaBHghwOTUyEgAUfSwgZmluZqMAEDk5NjcwATmiowAUNDI1NTc0MqMAHDExMS41NTjCYRwB0BmrGDQ0MDA5ODguqwAcOTUyMDc1cywZqw0SWUpBowAzYXgltRRub3QoZXE5mRgsIDcpKSwgARcUaXNudWxsGRsAKSHqBX4hFgBztS0ICTM4ka5hAxA1CTZfMyHVCDgwMF0VSpkEYb8AZaWGUiAFIHNjaGVtYV9pZAHhRsQFRf4JHklmCG1pbhWtADgyYQIAMUq3AAQyLHphAhwwMDE4NzY2c2ZhAgAxSUlRYRw1OTM2OTA0MkGUIalFYRQzNTguNDaJrwEVJUAwMTUuNTk0MjE2NzE3c1VpGDE4OTY0NTYh0E1pFRJ6aQIYMDI2NTE3NK6rABA2MTU3MAUzAZYJqxgwNy43OTLCPmkCHDU5NjUxNDkzQVehgSQzLjExOTM5OTQyARIRqxESWWkANsEFDDM2CTBJCqX7JEhhc2hBZ2dfMzE9lSExifEAMiFtAHCpEwAgNvYFDDIuMjnBg0E1ufQBvQESBDogxaCh92H7ECAxNzc2yRIlcQwgMS42IWrCAwYENDbNlmoDBjQsIFJlc29sdmVMb2NrOgG2HF9ycGM6MTc3gY7hQAmFLDg1Ni44bXN9CTE5N90zADdhMAAxpdn+MgPOMgNKWgMWmQh9QgA4Ja02HgYIMi4wJXMpud2qFDgJNDNfM4FmDDAJMTCBBGWqOqgGAGt2jgZhsppwAA==')
# Plan_digest: ae1f28c9bec84b2f3ff25dddc3b860cc6fff8524d66eb8eb50996995f37bdd0c
select job_meta, processing from mysql.tidb_ddl_job where job_id in (select min(job_id) from mysql.tidb_ddl_job group by schema_ids, table_ids, processing) and  reorg and job_id not in (7) order by processing desc, job_id;

It is unnormal, in my local machine, it only takes 0.5 ms, 6000x faster than ci env

mysql> explain analyze select job_meta, processing from mysql.tidb_ddl_job where job_id in (select min(job_id) from mysql.tidb_ddl_job group by schema_ids, table_ids, processing) and  reorg and job_id not in (5) order by processing desc, job_id;
+--------------------------------------+----------+---------+-----------+--------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| id                                   | estRows  | actRows | task      | access object      | execution info                                                                                                                                                                                                                                                                                                                               | operator info                                                                                                                                        | memory    | disk    |
+--------------------------------------+----------+---------+-----------+--------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
| Projection_13                        | 2222.22  | 0       | root      |                    | time:531.8µs, loops:1, RU:0.950671, Concurrency:5                                                                                                                                                                                                                                                                                            | mysql.tidb_ddl_job.job_meta, mysql.tidb_ddl_job.processing                                                                                           | 11.8 KB   | N/A     |
| └─Sort_14                            | 2222.22  | 0       | root      |                    | time:482.3µs, loops:1                                                                                                                                                                                                                                                                                                                        | mysql.tidb_ddl_job.processing:desc, mysql.tidb_ddl_job.job_id                                                                                        | 0 Bytes   | 0 Bytes |
|   └─HashJoin_28                      | 2222.22  | 0       | root      |                    | time:446µs, loops:1, build_hash_table:{total:194.1µs, fetch:194.1µs, build:0s}                                                                                                                                                                                                                                                               | inner join, equal:[eq(mysql.tidb_ddl_job.job_id, Column#15)]                                                                                         | 0 Bytes   | 0 Bytes |
|     ├─TableReader_41(Build)          | 2222.22  | 0       | root      |                    | time:126.4µs, loops:1, cop_task: {num: 1, max: 460.2µs, proc_keys: 0, rpc_num: 1, rpc_time: 425.1µs, copr_cache_hit_ratio: 0.00, build_task_duration: 11.8µs, max_distsql_concurrency: 1}                                                                                                                                                    | data:Selection_40                                                                                                                                    | 184 Bytes | N/A     |
|     │ └─Selection_40                 | 2222.22  | 0       | cop[tikv] |                    | tikv_task:{time:389.8µs, loops:0}                                                                                                                                                                                                                                                                                                            | mysql.tidb_ddl_job.reorg                                                                                                                             | N/A       | N/A     |
|     │   └─TableRangeScan_39          | 6666.67  | 0       | cop[tikv] | table:tidb_ddl_job | tikv_task:{time:389.8µs, loops:0}                                                                                                                                                                                                                                                                                                            | range:[-inf,5), (5,+inf], keep order:false, stats:pseudo                                                                                             | N/A       | N/A     |
|     └─HashAgg_29(Probe)              | 6400.00  | 0       | root      |                    | time:310.6µs, loops:1, partial_worker:{wall_time:268.292µs, concurrency:5, task_num:0, tot_wait:1.113251ms, tot_exec:0s, tot_time:1.117873ms, max:243.541µs, p95:243.541µs}, final_worker:{wall_time:300.25µs, concurrency:5, task_num:0, tot_wait:1.358917ms, tot_exec:5.874µs, tot_time:1.369583ms, max:284.5µs, p95:284.5µs}              | group by:Column#15, funcs:firstrow(Column#15)->Column#15                                                                                             | 9.86 KB   | N/A     |
|       └─Selection_30                 | 6400.00  | 0       | root      |                    | time:231µs, loops:1                                                                                                                                                                                                                                                                                                                          | not(eq(Column#15, 5)), not(isnull(Column#15))                                                                                                        | 380 Bytes | N/A     |
|         └─HashAgg_35                 | 8000.00  | 0       | root      |                    | time:219.5µs, loops:1, partial_worker:{wall_time:139.041µs, concurrency:5, task_num:0, tot_wait:592.083µs, tot_exec:0s, tot_time:597.542µs, max:125.334µs, p95:125.334µs}, final_worker:{wall_time:219.417µs, concurrency:5, task_num:0, tot_wait:724.794µs, tot_exec:33.875µs, tot_time:763.75µs, max:189.709µs, p95:189.709µs}             | group by:mysql.tidb_ddl_job.processing, mysql.tidb_ddl_job.schema_ids, mysql.tidb_ddl_job.table_ids, funcs:min(Column#18)->Column#15                 | 26.0 KB   | N/A     |
|           └─TableReader_36           | 8000.00  | 0       | root      |                    | time:112.8µs, loops:1, cop_task: {num: 1, max: 399.7µs, proc_keys: 0, rpc_num: 1, rpc_time: 359.8µs, copr_cache_hit_ratio: 0.00, build_task_duration: 2.21µs, max_distsql_concurrency: 1}                                                                                                                                                    | data:HashAgg_31                                                                                                                                      | 184 Bytes | N/A     |
|             └─HashAgg_31             | 8000.00  | 0       | cop[tikv] |                    | tikv_task:{time:318.1µs, loops:0}                                                                                                                                                                                                                                                                                                            | group by:mysql.tidb_ddl_job.processing, mysql.tidb_ddl_job.schema_ids, mysql.tidb_ddl_job.table_ids, funcs:min(mysql.tidb_ddl_job.job_id)->Column#18 | N/A       | N/A     |
|               └─TableFullScan_34     | 10000.00 | 0       | cop[tikv] | table:tidb_ddl_job | tikv_task:{time:318.1µs, loops:0}                                                                                                                                                                                                                                                                                                            | keep order:false, stats:pseudo                                                                                                                       | N/A       | N/A     |
+--------------------------------------+----------+---------+-----------+--------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------+-----------+---------+
12 rows in set (0.01 sec)

The maxium time consume is cop_time, ref for cop_time #16904 (comment)

log.txt

[Defined2014]

This is not a problem with this test cases. I think the root problem is why it is so slow at CI platform. The disk usage is too high or cpu usage is too high or something else?

[wuhuizuo]

It happened 27 times after 2023-09-14:

Report Time	Timecost Ms	Build URL
2023-09-14T02:41:53+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33135/
2023-09-14T11:47:54+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33155/
2023-09-14T11:49:40+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33161/
2023-09-14T13:26:00+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33187/
2023-09-14T15:33:57+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33202/
2023-09-14T18:32:31+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33249/
2023-09-14T18:42:56+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33254/
2023-09-14T19:05:22+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33256/
2023-09-15T16:32:29+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33361/
2023-09-15T20:54:10+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33383/
2023-09-16T15:08:26+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33400/
2023-09-18T12:16:36+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33429/
2023-09-18T16:13:26+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33464/
2023-09-18T16:40:57+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33470/
2023-09-18T22:27:35+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33515/
2023-09-19T14:41:37+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33566/
2023-09-20T08:57:38+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33638/
2023-09-20T17:21:49+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33694/
2023-09-21T00:58:40+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33745/
2023-09-21T01:34:36+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33747/
2023-09-22T13:06:59+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/33880/
2023-09-25T17:40:59+08:00	290960	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34086/
2023-09-25T17:53:40+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34080/
2023-09-25T19:07:17+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34112/
2023-09-25T19:45:47+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34114/
2023-09-26T11:06:15+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34170/
2023-09-27T15:37:56+08:00	timeout	https://do.pingcap.net/jenkins/job/pingcap/job/tidb/job/ghpr_unit_test/34302/

[wuhuizuo]

Average timecost was 293070.0000ms between "2023-11-10" AND "2023-11-22"

Found records: 5 (filter only for runs that timecost >= threshold)
Max timecost: 298500ms
Min timecost: 289430ms
Avg timecost: 293070.0000ms

• CI build: used 291540ms
• CI build: used 298500ms
• CI build: used 295400ms
• CI build: used 289430ms
• CI build: used 290480ms