DDL Adding Index Stuck

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: DDL加索引卡住

| username: hey-hoho

[TiDB Usage Environment] Production Environment
[TiDB Version] 6.5.5
[Reproduction Path] What operations were performed to encounter the issue

09:22:50 Execute the following SQL to add an index:
alter table wm_xxx add index idx_xxx(c1,c2)

[Encountered Issue: Problem Phenomenon and Impact]

After execution, it gets stuck, job_type is add index /* ingest */, state is write reorganization, row_count remains 0

Logs of the TiDB server executing the DDL:

[2024/04/09 09:22:51.021 +08:00] [Info] [ddl_worker.go:314] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:37449, Type:add index, State:queueing, SchemaState:none, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0; "] [table=true]
[2024/04/09 09:22:51.022 +08:00] [Info] [ddl.go:1011] ["[ddl] start DDL job"] [job="ID:37449, Type:add index, State:queueing, SchemaState:none, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"] [query="alter table wm_xxx add index idx_xxx(c1,c2)"]
[2024/04/09 09:22:51.077 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39676]
[2024/04/09 09:22:51.177 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39677]
[2024/04/09 09:22:51.227 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39678]

Relevant logs of the DDL owner:

[2024/04/09 09:22:51.047 +08:00] [Info] [ddl_worker.go:1186] ["[ddl] run DDL job"] [worker="worker 13, tp add index"] [job="ID:37449, Type:add index, State:queueing, SchemaState:none, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:0, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.050 +08:00] [Info] [index.go:605] ["[ddl] run add index job"] [job="ID:37449, Type:add index, State:running, SchemaState:none, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"] [indexInfo="{\"id\":7,\"idx_name\":{\"O\":\"idx_xxx\",\"L\":\"idx_xxx\"},\"tbl_name\":{\"O\":\"\",\"L\":\"\"},\"idx_cols\":[{\"name\":{\"O\":\"group_mater_flag\",\"L\":\"group_mater_flag\"},\"offset\":5,\"length\":-1},{\"name\":{\"O\":\"scan_flag\",\"L\":\"scan_flag\"},\"offset\":93,\"length\":-1}],\"state\":0,\"backfill_state\":0,\"comment\":\"\",\"index_type\":1,\"is_unique\":false,\"is_primary\":false,\"is_invisible\":false,\"is_global\":false}"]
[2024/04/09 09:22:51.100 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39676]
[2024/04/09 09:22:51.111 +08:00] [Info] [ddl_worker.go:1395] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=39676] ["take time"=52.592634ms] [job="ID:37449, Type:add index, State:running, SchemaState:delete only, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.120 +08:00] [Info] [ddl_worker.go:1186] ["[ddl] run DDL job"] [worker="worker 4, tp add index"] [job="ID:37449, Type:add index, State:running, SchemaState:delete only, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:0, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.150 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39677]
[2024/04/09 09:22:51.182 +08:00] [Info] [syncer.go:333] ["[ddl] syncer check all versions, someone is not synced"] [info="instance ip 10.0.6.65, port 4002, id 0a414933-16dc-4baa-b762-7a250aae380c"] ["ddl id"=37449] [ver=39677]
[2024/04/09 09:22:51.203 +08:00] [Info] [ddl_worker.go:1395] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=39677] ["take time"=73.441067ms] [job="ID:37449, Type:add index, State:running, SchemaState:write only, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.210 +08:00] [Info] [ddl_worker.go:1186] ["[ddl] run DDL job"] [worker="worker 6, tp add index"] [job="ID:37449, Type:add index, State:running, SchemaState:write only, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:0, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.249 +08:00] [Info] [domain.go:766] ["mdl gets lock, update to owner"] [jobID=37449] [version=39678]
[2024/04/09 09:22:51.271 +08:00] [Info] [ddl_worker.go:1395] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=39678] ["take time"=52.152977ms] [job="ID:37449, Type:add index, State:running, SchemaState:write reorganization, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.290 +08:00] [Info] [ddl_worker.go:1186] ["[ddl] run DDL job"] [worker="worker 7, tp add index"] [job="ID:37449, Type:add index, State:running, SchemaState:write reorganization, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:0, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, UniqueWarnings:0"]
[2024/04/09 09:22:51.292 +08:00] [Info] [index.go:800] ["[ddl] index backfill state running"] ["job ID"=37449] [table=wm_xxx] ["ingest mode"=true] [index=idx_xxx]
[2024/04/09 09:22:51.320 +08:00] [Info] [backend_mgr.go:74] ["[ddl-ingest] create one backend for an DDL job"] ["job ID"=37449] ["current memory usage"=136] ["max memory quota"=2147483648] ["is unique index"=false]
[2024/04/09 09:22:51.336 +08:00] [Info] [reorg.go:621] ["[ddl] job get table range"] [jobID=37449] [physicalTableID=7737] [startKey=748000000000001e395f728000000000000e10] [endKey=748000000000001e395f72800000000d500251]
[2024/04/09 09:22:51.355 +08:00] [Info] [ddl_worker.go:1186] ["[ddl] run DDL job"] [worker="worker 8, tp add index"] [job="ID:37449, Type:add index, State:running, SchemaState:write reorganization, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:0, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:448954570187473162, UniqueWarnings:0"]
[2024/04/09 09:22:51.358 +08:00] [Info] [index.go:800] ["[ddl] index backfill state running"] ["job ID"=37449] [table=wm_xxx] ["ingest mode"=true] [index=idx_xxx]
[2024/04/09 09:22:51.359 +08:00] [Info] [index.go:1682] ["[ddl] start to add table index"] [job="ID:37449, Type:add index, State:running, SchemaState:write reorganization, SchemaID:3642, TableID:7737, RowCount:0, ArgLen:6, start time: 2024-04-09 09:22:50.984 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:448954570187473162, UniqueWarnings:0"] [reorgInfo="CurrElementType:_idx_,CurrElementID:7,StartKey:748000000000001e395f728000000000000e10,EndKey:748000000000001e395f72800000000d500251,First:false,PhysicalTableID:7737,Ingest mode:true"]
[2024/04/09 09:22:51.386 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] open an engine for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=335544600] ["memory limitation"=2147483648] ["current writer count"=1]
[2024/04/09 09:22:51.411 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=0] ["allocate memory"=32] ["current memory usage"=335544632] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.411 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=402653496] ["memory limitation"=2147483648] ["current writer count"=2]
[2024/04/09 09:22:51.436 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=1] ["allocate memory"=32] ["current memory usage"=402653528] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.437 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=469762392] ["memory limitation"=2147483648] ["current writer count"=3]
[2024/04/09 09:22:51.461 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=2] ["allocate memory"=32] ["current memory usage"=469762424] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.461 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=536871288] ["memory limitation"=2147483648] ["current writer count"=4]
[2024/04/09 09:22:51.488 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=3] ["allocate memory"=32] ["current memory usage"=536871320] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.488 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=603980184] ["memory limitation"=2147483648] ["current writer count"=5]
[2024/04/09 09:22:51.514 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=4] ["allocate memory"=32] ["current memory usage"=603980216] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.514 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=671089080] ["memory limitation"=2147483648] ["current writer count"=6]
[2024/04/09 09:22:51.540 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=5] ["allocate memory"=32] ["current memory usage"=671089112] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.540 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["current memory usage"=738197976] ["memory limitation"=2147483648] ["current writer count"=7]
[2024/04/09 09:22:51.568 +08:00] [Info] [engine.go:170] ["[ddl-ingest] create one local writer for index reorg task"] ["job ID"=37449] ["index ID"=7] ["worker ID"=6] ["allocate memory"=32] ["current memory usage"=738198008] ["max memory quota"=2147483648]
[2024/04/09 09:22:51.568 +08:00] [Info] [engine_mgr.go:82] ["[ddl-ingest] reuse engine and add a writer for index reorg task"] ["job ID
| username: zhaokede | Original post link

Is the database still performing other large operations? The error indicates that concurrency has exceeded the limit.

| username: TiDBer_jYQINSnf | Original post link

I haven’t encountered this before. How about trying to reduce the tidb_ddl_reorg_worker_cnt parameters?
Or change the DDL owner?
These are suggestions without understanding the root cause. Meanwhile, focus on addressing the root cause of the problem.

| username: tidb菜鸟一只 | Original post link

Are you still running lightning synchronously? It might have triggered this bug Schema version update failure may cause DDL job to get stuck · Issue #43755 · pingcap/tidb (github.com)

| username: DBAER | Original post link

Using long transactions? Waiting for the previous DML to complete before the DDL metadata lock?

| username: DBAER | Original post link

Additionally, you can check if there are any locks.

| username: 小龙虾爱大龙虾 | Original post link

How much data is there in the table, and how long has it been running?

| username: hey-hoho | Original post link

The table has only over 1,000 rows, but it has been running for several hours.

| username: hey-hoho | Original post link

I didn’t run lightning, that lightning log should be for fast DDL.

| username: zhaokede | Original post link

For data tables with over 1,000 entries, indexes are generally added in seconds.

| username: terry0219 | Original post link

There should be a metadata lock here, right?

| username: terry0219 | Original post link

Is there a long transaction on a table that hasn’t been committed?

| username: 小龙虾爱大龙虾 | Original post link

Then there must be a problem. If it’s not an MDL lock, just restart if you can’t find the issue.

| username: hey-hoho | Original post link

Restarted everything but it didn’t work :rofl:

| username: hey-hoho | Original post link

When adding an index, there is no metadata lock and no other long transactions occupying it.

| username: terry0219 | Original post link

Try executing admin show ddl jobs; to take a look.

| username: virvle | Original post link

Use show processlist or admin show ddl jobs to view the currently executing DDL and its status.

| username: hughzm | Original post link

Check the process list. There are also metadata errors when executing DDL in MySQL.

| username: 霸王龙的日常 | Original post link

I encountered this issue in a previous project.
Solution:

  1. Check the DDL execution information
mysql> admin show ddl;

Pay attention to the OWNER_ADDRESS field value, for example, if it is 172.1.1.2:4000, the port is 4000.

  1. Create a directory
mkdir -p /tmp/tidb/tmp_ddl-4000
chown tidb:tidb /tmp/tidb/tmp_ddl-4000

Note: Replace 4000 with the actual port.

| username: 友利奈绪 | Original post link

Have you never tried it before or is it a recent issue?