Skip to content

multiple schema change can't complete while enable metadata lock #39090

Closed
#39093
Closed
multiple schema change can't complete while enable metadata lock#39090
#39093
Assignees
Defined2014
Labels
severity/majorsig/sql-infraSIG: SQL Infratype/bugThe issue is confirmed as a bug.
@aytrack

Description

@aytrack
aytrack
opened on Nov 11, 2022

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

  1. 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

Metadata

Metadata

Assignees

Labels

severity/majorsig/sql-infraSIG: SQL Infratype/bugThe issue is confirmed as a bug.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions