multiple schema change can't complete while enable metadata lock #39090
Description
Bug Report
Please answer these questions before submitting your issue. Thanks!
1. Minimal reproduce step (Required)
- deploy a cluster with tikv and execute the following sqls.
CREATE TABLE `account1` (
`uid` bigint(19) unsigned NOT NULL,
`status` int(1) unsigned NOT NULL,
`name` varchar(140) NOT NULL,
`password` varchar(9) NOT NULL,
`deposit_switch` int(1) unsigned NOT NULL,
`draw_switch` int(1) unsigned NOT NULL,
`institution_id` int(10) unsigned NOT NULL,
`employee_id` bigint(11) unsigned NOT NULL,
`update_time` date NOT NULL,
`sign_time` date NOT NULL,
`logout_time` date NOT NULL,
index indx(name),
index indx2(uid),
index indx3(update_time),
PRIMARY KEY (`uid`,`update_time`)
);
ALTER TABLE
account1
ADD
COLUMN b INT,
ADD
INDEX idx(employee_id),
alter column
status
set
default 1,
alter index indx invisible,
MODIFY COLUMN password varCHAR(11),
drop index indx2,
rename column deposit_switch to deposit2_switch,
rename index indx3 to idx3,
COMMENT = 'comments for t';
admin show ddl jobs;2. What did you expect to see? (Required)
the ddl should be synced
+--------+---------+--------------------+-------------------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
| JOB_ID | DB_NAME | TABLE_NAME | JOB_TYPE | SCHEMA_STATE | SCHEMA_ID | TABLE_ID | ROW_COUNT | CREATE_TIME | START_TIME | END_TIME | STATE |
+--------+---------+--------------------+-------------------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
| 72 | test | account1 | alter table multi-schema change | none | 2 | 70 | 0 | 2022-11-11 17:40:50 | 2022-11-11 17:40:50 | 2022-11-11 17:40:53 | synced |
| 72 | test | account1 | add column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | add index /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | set default value /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | alter index visibility /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | drop index /* subjob */ | none | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | rename index /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify table comment /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |3. What did you see instead (Required)
It can not stop for a long time. It works ok without tikv.
+--------+---------+----------------------------------+-------------------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
| JOB_ID | DB_NAME | TABLE_NAME | JOB_TYPE | SCHEMA_STATE | SCHEMA_ID | TABLE_ID | ROW_COUNT | CREATE_TIME | START_TIME | END_TIME | STATE |
+--------+---------+----------------------------------+-------------------------------------+--------------+-----------+----------+-----------+---------------------+---------------------+---------------------+--------+
| 72 | test | account1 | alter table multi-schema change | none | 2 | 70 | 0 | 2022-11-11 17:46:58 | 2022-11-11 17:46:58 | <null> | done |
| 72 | test | account1 | add column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | add index /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | set default value /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | alter index visibility /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | drop index /* subjob */ | none | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify column /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | rename index /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 72 | test | account1 | modify table comment /* subjob */ | public | 2 | 70 | 0 | <null> | <null> | <null> | done |
| 71 | test | account1 | create table | public | 2 | 70 | 0 | 2022-11-11 17:46:58 | 2022-11-11 17:46:58 | 2022-11-11 17:46:58 | synced |tidb log
[2022/11/11 17:46:58.839 +08:00] [INFO] [session.go:3329] ["CRUCIAL OPERATION"] [conn=5694836913182081431] [schemaVersion=35] [cur_db=test] [sql="ALTER TABLE\n account1\nADD\n COLUMN b INT,\nADD\n INDEX idx(employee_id),\nalter column\n status\nset\n default 1,\n alter index indx invisible,\n MODIFY COLUMN password varCHAR(11),\n drop index indx2,\n rename column deposit_switch to deposit2_switch,\n rename index indx3 to idx3,\n COMMENT = 'comments for t'"] [user=root@%]
[2022/11/11 17:46:58.866 +08:00] [INFO] [split_region.go:187] ["batch split regions complete"] ["batch region ID"=10] ["first at"=748000000000000046] ["first new region left"="{Id:78 StartKey:7480000000000000ff4400000000000000f8 EndKey:7480000000000000ff4600000000000000f8 RegionEpoch:{ConfVer:1 Version:39} Peers:[id:79 store_id:1 ] EncryptionMeta:<nil> IsInFlashback:false}"] ["new region count"=1]
[2022/11/11 17:46:58.866 +08:00] [INFO] [split_region.go:236] ["split regions complete"] ["region count"=1] ["region IDs"="[78]"]
[2022/11/11 17:46:58.877 +08:00] [INFO] [ddl_worker.go:314] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:72, Type:alter table multi-schema change, State:queueing, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2022/11/11 17:46:58.878 +08:00] [INFO] [ddl.go:1012] ["[ddl] start DDL job"] [job="ID:72, Type:alter table multi-schema change, State:queueing, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="ALTER TABLE\n account1\nADD\n COLUMN b INT,\nADD\n INDEX idx(employee_id),\nalter column\n status\nset\n default 1,\n alter index indx invisible,\n MODIFY COLUMN password varCHAR(11),\n drop index indx2,\n rename column deposit_switch to deposit2_switch,\n rename index indx3 to idx3,\n COMMENT = 'comments for t'"]
[2022/11/11 17:46:58.947 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 10, tp add index"] [job="ID:72, Type:add column, State:queueing, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:58.948 +08:00] [INFO] [column.go:132] ["[ddl] run add column job"] [job="ID:72, Type:add column, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:4, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"] [columnInfo="{\"id\":12,\"name\":{\"O\":\"b\",\"L\":\"b\"},\"offset\":11,\"origin_default\":null,\"origin_default_bit\":null,\"default\":null,\"default_bit\":null,\"default_is_expr\":false,\"generated_expr_string\":\"\",\"generated_stored\":false,\"dependences\":null,\"type\":{},\"state\":0,\"comment\":\"\",\"hidden\":false,\"change_state_info\":null,\"version\":2}"]
[2022/11/11 17:46:59.005 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=35] [neededSchemaVersion=36] ["start time"=1.654402ms] [phyTblIDs="[70]"] [actionTypes="[32]"]
[2022/11/11 17:46:59.065 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=36]
[2022/11/11 17:46:59.181 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=36] ["take time"=223.739731ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/11/11 17:46:59.190 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 9, tp add index"] [job="ID:72, Type:add column, State:running, SchemaState:delete only, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:59.309 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=36] [neededSchemaVersion=37] ["start time"=4.275595ms] [phyTblIDs="[70]"] [actionTypes="[32]"]
[2022/11/11 17:46:59.365 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=37]
[2022/11/11 17:46:59.502 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=37] ["take time"=300.282157ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/11/11 17:46:59.536 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 10, tp add index"] [job="ID:72, Type:add column, State:running, SchemaState:write only, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:59.587 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=37] [neededSchemaVersion=38] ["start time"=1.484178ms] [phyTblIDs="[70]"] [actionTypes="[32]"]
[2022/11/11 17:46:59.665 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=38]
[2022/11/11 17:46:59.693 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=38] ["take time"=127.358104ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/11/11 17:46:59.700 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 9, tp add index"] [job="ID:72, Type:add index, State:queueing, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:59.700 +08:00] [INFO] [index.go:602] ["[ddl] run add index job"] [job="ID:72, Type:add index, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:6, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"] [indexInfo="{\"id\":5,\"idx_name\":{\"O\":\"idx\",\"L\":\"idx\"},\"tbl_name\":{\"O\":\"\",\"L\":\"\"},\"idx_cols\":[{\"name\":{\"O\":\"employee_id\",\"L\":\"employee_id\"},\"offset\":7,\"length\":-1}],\"state\":0,\"backfill_state\":0,\"comment\":\"\",\"index_type\":1,\"is_unique\":false,\"is_primary\":false,\"is_invisible\":false,\"is_global\":false}"]
[2022/11/11 17:46:59.721 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=38] [neededSchemaVersion=39] ["start time"=1.269185ms] [phyTblIDs="[70]"] [actionTypes="[128]"]
[2022/11/11 17:46:59.765 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=39]
[2022/11/11 17:46:59.797 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=39] ["take time"=91.434799ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/11/11 17:46:59.807 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 10, tp add index"] [job="ID:72, Type:add index, State:running, SchemaState:delete only, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:59.831 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=39] [neededSchemaVersion=40] ["start time"=1.132431ms] [phyTblIDs="[70]"] [actionTypes="[128]"]
[2022/11/11 17:46:59.865 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=40]
[2022/11/11 17:46:59.922 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=40] ["take time"=105.537181ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/11/11 17:46:59.934 +08:00] [INFO] [ddl_worker.go:1157] ["[ddl] run DDL job"] [worker="worker 10, tp add index"] [job="ID:72, Type:add index, State:running, SchemaState:write only, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0, Multi-Schema Change:true, Revertible:true"]
[2022/11/11 17:46:59.968 +08:00] [INFO] [domain.go:188] ["diff load InfoSchema success"] [currentSchemaVersion=40] [neededSchemaVersion=41] ["start time"=1.90314ms] [phyTblIDs="[70]"] [actionTypes="[128]"]
[2022/11/11 17:47:00.016 +08:00] [INFO] [domain.go:720] ["mdl gets lock, update to owner"] [jobID=72] [version=41]
[2022/11/11 17:47:00.065 +08:00] [INFO] [ddl_worker.go:1362] ["[ddl] wait latest schema version changed(get the metadata lock if tidb_enable_metadata_lock is true)"] [ver=41] ["take time"=116.201966ms] [job="ID:72, Type:alter table multi-schema change, State:running, SchemaState:none, SchemaID:2, TableID:70, RowCount:0, ArgLen:0, start time: 2022-11-11 17:46:58.795 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
...
[2022/11/11 17:47:58.928 +08:00] [WARN] [expensivequery.go:114] [expensive_query] [cost_time=60.085034311s] [conn_id=5694836913182081431] [user=root] [database=test] [txn_start_ts=0] [mem_max="0 Bytes (0 Bytes)"] [sql="ALTER TABLE\n account1\nADD\n COLUMN b INT,\nADD\n INDEX idx(employee_id),\nalter column\n status\nset\n default 1,\n alter index indx invisible,\n MODIFY COLUMN password varCHAR(11),\n drop index indx2,\n rename column deposit_switch to deposit2_switch,\n rename index indx3 to idx3,\n COMMENT = 'comments for t'"]
4. What is your TiDB version? (Required)
TiDB root@127.0.0.1:(none)> select tidb_version()\G
***************************[ 1. row ]***************************
tidb_version() | Release Version: v6.5.0-alpha
Edition: Community
Git Commit Hash: 9dc8bc935b600cca8d2e1e083c8733bfea199be8
Git Branch: heads/refs/tags/v6.5.0-alpha
UTC Build Time: 2022-11-09 14:24:49
GoVersion: go1.19.2
Race Enabled: false
TiKV Min Version: 6.2.0-alpha
Check Table Before Drop: false
Store: tikv