Add and drop index 1000 times, DDL hang #58344
Description
Bug Report
Please answer these questions before submitting your issue. Thanks!
1. Minimal reproduce step (Required)
func TestXXX(t *testing.T) {
store, dom := testkit.CreateMockStoreAndDomain(t)
tk := testkit.NewTestKit(t, store)
tk.MustExec("use test")
tk.MustExec("create table xx (id int, c int)")
for i:=0; i<1000; i++ {
tk.MustExec("alter table xx add index i_c(c)")
tk.MustExec("alter table xx drop index i_c")
fmt.Println("current --- ", i)
}
is := dom.InfoSchema()
ok, v2 := infoschema.IsV2(is)
if ok {
v2.IterateAllTableItems(func(ti infoschema.TableItem) bool {
return true
})
}
}
2. What did you expect to see? (Required)
Test pass
3. What did you see instead (Required)
Test hang,
[2024/12/17 15:58:19.612 +08:00] [INFO] [session.go:4114] ["CRUCIAL OPERATION"] [conn=1] [schemaVersion=10045] [cur_db=test] [sql="alter table xx drop index i_c"] [user=]
current --- 998
[2024/12/17 15:58:19.612 +08:00] [INFO] [executor.go:4989] ["initialize reorg meta"] [category=ddl] [jobSchema=test] [jobTable=xx] [jobType="add index"] [enableDistTask=true] [enableFastReorg=true] [targetScope=] [concurrency=4] [batchSize=256]
[2024/12/17 15:58:19.615 +08:00] [INFO] [job_submitter.go:133] ["add DDL jobs"] [category=ddl] ["batch count"=1] [jobs="ID:2110, Type:add index, State:queueing, SchemaState:none, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0; "] [fast_create=true]
[2024/12/17 15:58:19.615 +08:00] [INFO] [executor.go:6615] ["DDL job submitted"] [category=ddl] [job="ID:2110, Type:add index, State:queueing, SchemaState:none, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"] [query="alter table xx add index i_c(c)"]
[2024/12/17 15:58:19.616 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:queueing, SchemaState:none, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.616 +08:00] [INFO] [index.go:708] ["[ddl] run add index job"] [category=ddl] [job="ID:2110, Type:add index, State:running, SchemaState:none, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"] [indexInfo="{\"id\":1000,\"idx_name\":{\"O\":\"i_c\",\"L\":\"i_c\"},\"tbl_name\":{\"O\":\"\",\"L\":\"\"},\"idx_cols\":[{\"name\":{\"O\":\"c\",\"L\":\"c\"},\"offset\":1,\"length\":-1}],\"state\":0,\"backfill_state\":0,\"comment\":\"\",\"index_type\":1,\"is_unique\":false,\"is_primary\":false,\"is_invisible\":false,\"is_global\":false,\"mv_index\":false,\"vector_index\":null}"]
[2024/12/17 15:58:19.616 +08:00] [INFO] [index.go:1292] ["fallback to txn-merge backfill process"] [category=ddl] ["lightning env initialized"=false]
[2024/12/17 15:58:19.620 +08:00] [INFO] [domain.go:353] ["diff load InfoSchema success"] [isV2=true] [currentSchemaVersion=10045] [neededSchemaVersion=10046] ["elapsed time"=2.615125ms] [gotSchemaVersion=10046] [phyTblIDs="[110]"] [actionTypes="[7]"] [diffTypes="[\"add index\"]"]
[2024/12/17 15:58:19.621 +08:00] [INFO] [schema_validator.go:305] ["the schema validator enqueue, queue is too long"] ["delta max count"=1024] ["remove schema version"=5685]
[2024/12/17 15:58:19.622 +08:00] [INFO] [domain.go:1112] ["mdl gets lock, update self version to owner"] [jobID=2110] [version=10046]
[2024/12/17 15:58:19.624 +08:00] [INFO] [schema_version.go:390] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=10046] ["take time"=6.456318ms] [job="ID:2110, Type:add index, State:running, SchemaState:delete only, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.626 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:running, SchemaState:delete only, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.630 +08:00] [INFO] [domain.go:353] ["diff load InfoSchema success"] [isV2=true] [currentSchemaVersion=10046] [neededSchemaVersion=10047] ["elapsed time"=2.429855ms] [gotSchemaVersion=10047] [phyTblIDs="[110]"] [actionTypes="[7]"] [diffTypes="[\"add index\"]"]
[2024/12/17 15:58:19.631 +08:00] [INFO] [domain.go:1112] ["mdl gets lock, update self version to owner"] [jobID=2110] [version=10047]
[2024/12/17 15:58:19.633 +08:00] [INFO] [schema_version.go:390] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=10047] ["take time"=5.0647ms] [job="ID:2110, Type:add index, State:running, SchemaState:write only, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.634 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:running, SchemaState:write only, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.639 +08:00] [INFO] [domain.go:353] ["diff load InfoSchema success"] [isV2=true] [currentSchemaVersion=10047] [neededSchemaVersion=10048] ["elapsed time"=3.135794ms] [gotSchemaVersion=10048] [phyTblIDs="[110]"] [actionTypes="[7]"] [diffTypes="[\"add index\"]"]
[2024/12/17 15:58:19.642 +08:00] [INFO] [domain.go:1112] ["mdl gets lock, update self version to owner"] [jobID=2110] [version=10048]
[2024/12/17 15:58:19.643 +08:00] [INFO] [schema_version.go:390] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=10048] ["take time"=6.689208ms] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.645 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.645 +08:00] [INFO] [index.go:1365] ["table is empty, skipping reorg work"] [category=ddl] [jobID=2110] [table=xx]
[2024/12/17 15:58:19.651 +08:00] [INFO] [domain.go:353] ["diff load InfoSchema success"] [isV2=true] [currentSchemaVersion=10048] [neededSchemaVersion=10049] ["elapsed time"=3.383623ms] [gotSchemaVersion=10049] [phyTblIDs="[110]"] [actionTypes="[7]"] [diffTypes="[\"add index\"]"]
[2024/12/17 15:58:19.653 +08:00] [INFO] [domain.go:1112] ["mdl gets lock, update self version to owner"] [jobID=2110] [version=10049]
[2024/12/17 15:58:19.654 +08:00] [INFO] [schema_version.go:390] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=10049] ["take time"=6.516158ms] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.657 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.657 +08:00] [INFO] [index.go:1381] ["index backfill state ready to merge"] [category=ddl] ["job ID"=2110] [table=xx] [index=i_c]
[2024/12/17 15:58:19.663 +08:00] [INFO] [domain.go:353] ["diff load InfoSchema success"] [isV2=true] [currentSchemaVersion=10049] [neededSchemaVersion=10050] ["elapsed time"=3.084314ms] [gotSchemaVersion=10050] [phyTblIDs="[110]"] [actionTypes="[7]"] [diffTypes="[\"add index\"]"]
[2024/12/17 15:58:19.665 +08:00] [INFO] [domain.go:1112] ["mdl gets lock, update self version to owner"] [jobID=2110] [version=10050]
[2024/12/17 15:58:19.666 +08:00] [INFO] [schema_version.go:390] ["wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [category=ddl] [ver=10050] ["take time"=6.406188ms] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:1, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.668 +08:00] [INFO] [job_worker.go:784] ["run DDL job"] [category=ddl] [jobID=2110] [conn=1] [job="ID:2110, Type:add index, State:running, SchemaState:write reorganization, SchemaID:2, TableID:110, RowCount:0, ArgLen:0, start time: 2024-12-17 15:58:19.614 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Version: v2, UniqueWarnings:0"]
[2024/12/17 15:58:19.668 +08:00] [INFO] [index.go:1403] ["temp index is empty, skipping reorg work"] [category=ddl] [jobID=2110] [table=xx]
[2024/12/17 15:58:19.832 +08:00] [INFO] [schema_validator.go:305] ["the schema validator enqueue, queue is too long"] ["delta max count"=1024] ["remove schema version"=5691]
[2024/12/17 16:03:48.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=5m28.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:04:18.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=5m58.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:04:48.333 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=6m28.665s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:05:18.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=6m58.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:05:48.333 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=7m28.665s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:06:18.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=7m58.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:06:48.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=8m28.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:07:18.332 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=8m58.664s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:07:48.333 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=9m28.665s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]
[2024/12/17 16:08:18.333 +08:00] [INFO] [txn.go:99] ["An internal transaction running by internal session lasts long time"] [time=9m58.665s] [startTS=454668399324168192] ["start time"=2024/12/17 15:58:19.668 +08:00]