Add index with distributed global sort performance is unstable

[tangenta]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

go-ycsb run mysql -P /ycsb/workloads/workloada -p mysql.host=xxx.xxx.xxx.xx -p mysql.port=xxxxx -p mysql.db=test -p threadcount=100 -p recordcount=100000000 -p operationcount=50000000 -p workload=core -p fieldcount=10 -p fieldlength=100 -p requestdistribution=uniform

alter table usertable add index test_idx(FIELD0);

2. What did you expect to see? (Required)

The execution time should be stable.

3. What did you see instead (Required)

(drop index statements are omitted)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (2 min 27.07 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (3 min 6.07 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (3 min 9.06 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (2 min 36.06 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (2 min 42.08 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (3 min 23.18 sec)

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (3 min 24.68 sec)

4. What is your TiDB version? (Required)

6ad9cac

[tangenta]

Let's take job 108 and job 112 as examples:

jobID = 108

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (2 min 27.07 sec)

2024-06-18 15:38:56.479000 | 2024-06-18 15:41:22.279000

jobID = 112

mysql> alter table usertable add index test_idx(FIELD0);
Query OK, 0 rows affected (3 min 9.06 sec)

2024-06-18 15:48:32.879000 | 2024-06-18 15:51:39.829000

I grabbed the log about these two jobs:

[2024/06/18 15:38:57.834 +08:00] [INFO] [backend_mgr.go:182] ["create local backend for adding index"] [category=ddl-ingest] [sortDir=/tiup/deploy/tmp_ddl-4000/108] [keyspaceName=]
[2024/06/18 15:39:56.628 +08:00] [INFO] [backfilling_read_index.go:139] ["read index executor cleanup subtask exec env"]
[2024/06/18 15:40:01.163 +08:00] [INFO] [backfilling_import_cloud.go:65] ["cloud import executor init subtask exec env"]
[2024/06/18 15:40:42.945 +08:00] [INFO] [local.go:1379] ["import engine success"] [category=ddl-ingest] [uuid=63ee8aff-60c8-5d25-8980-fd5ac91e7f50] [size=4900000000] [kvs=0] [importedSize=4904115951] [importedCount=33361333]
[2024/06/18 15:40:46.203 +08:00] [INFO] [index.go:1975] ["start to merge temp index"] [category=ddl] [job="ID:108, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:104, RowCount:100000000, ArgLen:6, start time: 2024-06-18 15:38:56.479 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:450545961187147894, LocalMode: false, UniqueWarnings:0"] [reorgInfo="CurrElementType:_idx_,CurrElementID:3,StartKey:7480000000000000685f69ffff000000000003,EndKey:7480000000000000685f69ffff000000000003ff,First:false,PhysicalTableID:104,Ingest mode:false"]
[2024/06/18 15:40:46.205 +08:00] [INFO] [backfilling.go:432] ["split table range from PD"] [category=ddl] [physicalTableID=104] ["start key"=7480000000000000685f69ffff000000000003] ["end key"=7480000000000000685f69ffff000000000003ff]
[2024/06/18 15:40:46.335 +08:00] [INFO] [backfilling.go:491] ["get backfill range task, change end key"] [category=ddl] [id=1] [pTbl=104] ["end key"=7480000000000000685f69ffff000000000003ff] ["current end key"=7480000000000000685f69ffff000000000003017a7a7a6e76694973ff6b48476674547a78ff4e6d714f5a4c7976ff45454646746a5576ff6f6f477151704e58ff74554a6c66536d6aff46784e4e42437267ff5a754f5375784b6cff6864677a4d71576aff714f74465751744eff487264476e634f74ff7843567476726371ff774a694e00000000fb038000000005ad38d000]
[2024/06/18 15:41:22.195 +08:00] [INFO] [backfilling.go:346] ["backfill worker finish task"] [category=ddl] [worker="backfill-worker 0, tp merge temporary index"] [task="taskID: 1, physicalTableID: 104, range: [7480000000000000685f69ffff000000000003, 7480000000000000685f69ffff000000000003017a7a7a6e76694973ff6b48476674547a78ff4e6d714f5a4c7976ff45454646746a5576ff6f6f477151704e58ff74554a6c66536d6aff46784e4e42437267ff5a754f5375784b6cff6864677a4d71576aff714f74465751744eff487264476e634f74ff7843567476726371ff774a694e00000000fb038000000005ad38d000), jobID: 108"] ["added count"=215442] ["scan count"=215442] ["next key"=7480000000000000685f69ffff000000000003017a7a7a6e76694973ff6b48476674547a78ff4e6d714f5a4c7976ff45454646746a5576ff6f6f477151704e58ff74554a6c66536d6aff46784e4e42437267ff5a754f5375784b6cff6864677a4d71576aff714f74465751744eff487264476e634f74ff7843567476726371ff774a694e00000000fb038000000005ad38d00000] ["take time"=35.85951182s]
[2024/06/18 15:41:22.195 +08:00] [INFO] [backfilling.go:636] ["backfill workers successfully processed"] [category=ddl] [element=ID:3,TypeKey:_idx_] ["total added count"=100215442] ["start key"=7480000000000000685f69ffff000000000003]
[2024/06/18 15:41:23.502 +08:00] [INFO] [ddl.go:1317] ["DDL job is finished"] [category=ddl] [jobID=108]

[2024/06/18 15:48:34.150 +08:00] [INFO] [backend_mgr.go:160] ["create one backend for an DDL job"] ["job ID"=112] ["current memory usage"=144] ["max memory quota"=25501368320] ["has unique index"=false]
[2024/06/18 15:49:39.837 +08:00] [INFO] [backfilling_read_index.go:139] ["read index executor cleanup subtask exec env"]
[2024/06/18 15:49:43.466 +08:00] [INFO] [backfilling_import_cloud.go:65] ["cloud import executor init subtask exec env"]
[2024/06/18 15:50:29.321 +08:00] [INFO] [local.go:1379] ["import engine success"] [category=ddl-ingest] [uuid=20b8c4fd-1303-5ba0-b76c-9a8e54a77fc1] [size=4900000000] [kvs=0] [importedSize=4902465582] [importedCount=33350106]
[2024/06/18 15:50:30.051 +08:00] [INFO] [index.go:1975] ["start to merge temp index"] [category=ddl] [job="ID:112, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:104, RowCount:100000000, ArgLen:6, start time: 2024-06-18 15:48:32.829 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:450546114239922301, LocalMode: false, UniqueWarnings:0"] [reorgInfo="CurrElementType:_idx_,CurrElementID:5,StartKey:7480000000000000685f69ffff000000000005,EndKey:7480000000000000685f69ffff000000000005ff,First:false,PhysicalTableID:104,Ingest mode:false"]
[2024/06/18 15:50:30.058 +08:00] [INFO] [backfilling.go:432] ["split table range from PD"] [category=ddl] [physicalTableID=104] ["start key"=7480000000000000685f69ffff000000000005] ["end key"=7480000000000000685f69ffff000000000005ff]
[2024/06/18 15:51:00.245 +08:00] [INFO] [backfilling.go:491] ["get backfill range task, change end key"] [category=ddl] [id=1] [pTbl=104] ["end key"=7480000000000000685f69ffff000000000005ff] ["current end key"=7480000000000000685f69ffff000000000005017a7a7a7a446b5361ff48525844525a6f76ff6443416379656955ff4e74765861775343ff5856667076796966ff456a475272647752ff6b4b416443514f73ff64614c57595a644eff6e4c6e5a6c74424aff53596751624b4448ff695a647142784c70ff4e586f506a535179ff434d726e00000000fb038000000002e55a3800]
[2024/06/18 15:51:39.753 +08:00] [INFO] [backfilling.go:346] ["backfill worker finish task"] [category=ddl] [worker="backfill-worker 0, tp merge temporary index"] [task="taskID: 1, physicalTableID: 104, range: [7480000000000000685f69ffff000000000005, 7480000000000000685f69ffff000000000005017a7a7a7a446b5361ff48525844525a6f76ff6443416379656955ff4e74765861775343ff5856667076796966ff456a475272647752ff6b4b416443514f73ff64614c57595a644eff6e4c6e5a6c74424aff53596751624b4448ff695a647142784c70ff4e586f506a535179ff434d726e00000000fb038000000002e55a3800), jobID: 112"] ["added count"=219534] ["scan count"=219534] ["next key"=7480000000000000685f69ffff000000000005017a7a7a7a446b5361ff48525844525a6f76ff6443416379656955ff4e74765861775343ff5856667076796966ff456a475272647752ff6b4b416443514f73ff64614c57595a644eff6e4c6e5a6c74424aff53596751624b4448ff695a647142784c70ff4e586f506a535179ff434d726e00000000fb038000000002e55a380000] ["take time"=39.508107016s]
[2024/06/18 15:51:39.753 +08:00] [INFO] [backfilling.go:636] ["backfill workers successfully processed"] [category=ddl] [element=ID:5,TypeKey:_idx_] ["total added count"=100219534] ["start key"=7480000000000000685f69ffff000000000005]
[2024/06/18 15:51:41.884 +08:00] [INFO] [ddl.go:1317] ["DDL job is finished"] [category=ddl] [jobID=112]

Here is the summary:

          job 108 v.s. job 112
total        146s v.s. 187s
read index    59s v.s.  65s
switch stage   5s v.s.   4s
import        41s v.s.  46s
switch stage   4s v.s.   1s
merge temp    36s v.s.  69s
- get-endK    0s  v.s.  30s

It takes too long for job 112 to "get backfill range task, change end key".