Tidb: Parallel truncate table & add index possible race condition

Created on 25 Jul 2017  路  3Comments  路  Source: pingcap/tidb 
ALTER TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b` ADD INDEX `711bb866-2df5-4724-a450-b3d41fe52869` (`6a913c6f-926d-4bd1-949f-ea72a7bb233b`);
TRUNCATE TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b`;

When SQL above are executed in parallel, sometimes ADD INDEX will fail with error:

ERROR: Error 1146: Table '%!s(MISSING).%!s(MISSING)' doesn't exist

Besides, when failing with errors, ADD INDEX also costs notable time (normal: <0.2s, error: ~4s)

  • When executed in serial in TiDB, no errors so far.
  • When executed in parallel in MySQL, no errors so far.

TiDB log:

2017/07/25 13:57:37 ddl.go:401: [info] [ddl] start DDL job ID:1318, Type:truncate table, State:none, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:1, Query:
TRUNCATE TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b`
2017/07/25 13:57:37 ddl_worker.go:262: [info] [ddl] run DDL job ID:1318, Type:truncate table, State:none, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:0
2017/07/25 13:57:37 domain.go:93: [info] [ddl] diff load InfoSchema from version 1893 to 1894, in 1.348769ms
2017/07/25 13:57:37 ddl_worker.go:368: [info] [ddl] wait latest schema version 1894 changed, take time 52.478148ms
2017/07/25 13:57:37 ddl_worker.go:117: [info] [ddl] finish DDL job ID:1318, Type:truncate table, State:synced, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:0
2017/07/25 13:57:37 ddl.go:438: [info] [ddl] DDL job 1318 is finished
2017/07/25 13:57:37 domain.go:354: [info] [ddl] on DDL change, must reload
2017/07/25 13:57:37 bg_worker.go:70: [info] [ddl] run background job ID:1318, Type:truncate table, State:none, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:0
2017/07/25 13:57:37 reorg.go:170: [info] [ddl] deleted 246 keys take time 0.014289436, deleted 246 keys in total
2017/07/25 13:57:37 bg_worker.go:129: [info] [ddl] finish background job ID:1318, Type:truncate table, State:done, SchemaState:none, SchemaID:1, TableID:1303, RowCount:246, ArgLen:1
2017/07/25 13:57:38 2pc.go:548: [info] 2PC clean up done, tid: 393468250135199748
2017/07/25 13:57:38 txn.go:56: [warning] [kv] Retry txn 393468250135199748 original txn 393468250135199748 err [try again later]: tikv restarts txn: Txn(Mvcc(WriteConflict))
2017/07/25 13:57:38 ddl.go:401: [info] [ddl] start DDL job ID:1319, Type:add index, State:none, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:4, Query:
ALTER TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b` ADD INDEX `711bb866-2df5-4724-a450-b3d41fe52869` (`6a913c6f-926d-4bd1-949f-ea72a7bb233b`)
2017/07/25 13:57:38 ddl_worker.go:262: [info] [ddl] run DDL job ID:1319, Type:add index, State:none, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:0
2017/07/25 13:57:38 ddl_worker.go:313: [info] [ddl] the DDL job is normal to cancel because [schema:1146]Table '%s.%s' doesn't exist
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/table.go:165: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/index.go:186: 
2017/07/25 13:57:38 ddl_worker.go:117: [info] [ddl] finish DDL job ID:1319, Type:add index, State:cancelled, SchemaState:none, SchemaID:1, TableID:1303, RowCount:0, ArgLen:0
2017/07/25 13:57:41 adapter.go:216: [warning] [268][TIME_QUERY] 3.179905513s ALTER TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b` ADD INDEX `711bb866-2df5-4724-a450-b3d41fe52869` (`6a913c6f-926d-4bd1-949f-ea72a7bb233b`)
2017/07/25 13:57:41 tidb.go:166: [info] RollbackTxn for ddl/autocommit error. 
2017/07/25 13:57:41 txn.go:174: [info] [kv] Rollback txn 393468250135199747
2017/07/25 13:57:41 session.go:623: [warning] [268] session error:
[schema:1146]Table '%s.%s' doesn't exist
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl.go:442: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl.go:451: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl_api.go:1415: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl_api.go:838: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/ddl.go:227: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/ddl.go:74: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/adapter.go:182: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/tidb.go:172: 
{
  "currDBName": "test",
  "id": 268,
  "status": 2,
  "strictMode": true,
  "user": "[email protected]"
}
2017/07/25 13:57:41 conn.go:377: [warning] [268] dispatch error:
id:268, addr:127.0.0.1:51693 status:2, collation:utf8_general_ci, user:root
ALTER TABLE `4d34f858-8cc0-4e9e-ba82-10633ac6011b` ADD INDEX `711bb866-2df5-4724-a450-b3d41fe52869` (`6a913c6f-926d-4bd1-949f-ea72a7bb233b`)
[schema:1146]Table '%s.%s' doesn't exist
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl.go:442: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl.go:451: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl_api.go:1415: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/ddl/ddl_api.go:838: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/ddl.go:227: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/ddl.go:74: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/executor/adapter.go:182: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/tidb.go:172: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/session.go:625: 
/Users/Breezewish/PingCAP/src/github.com/pingcap/tidb/server/conn.go:681: 
2017/07/25 13:57:41 server.go:211: [info] [268] close connection
severitmoderate siinfra typbug
Source
picture breeswish

Most helpful comment

@breeswish @Kansuler In TiDB, DDL jobs will run in sequence one by one. So in this case, truncate table will be converted into two jobs, one is drop table, another one is create table with the same name and schema. So if the sequence is DropTable, AlterTable, CreateTable, then the AlterTable will found not table with that name.
It is indeed a problem, but not a serious one. We will handle this in the future.

picture shenli on 4 Aug 2017
👍3

All 3 comments

I think I am having the same problem. When I have several parallel containers in kubernetes that try to truncate a table. It seems to cause some kind of race which causes that error.

2017/08/04 00:53:34 ddl_worker.go:117: [info] [ddl] finish DDL job ID:451, Type:truncate table, State:cancelled, SchemaState:none, SchemaID:432, TableID:442, RowCount:0, ArgLen:1
2017/08/04 00:53:34 adapter.go:216: [warning] [103][TIME_QUERY] 970.430407ms TRUNCATE `schema_migrations`
2017/08/04 00:53:34 tidb.go:166: [info] RollbackTxn for ddl/autocommit error. 
2017/08/04 00:53:34 txn.go:174: [info] [kv] Rollback txn 393689959933149185
2017/08/04 00:53:34 session.go:623: [warning] [103] session error:
[schema:1146]Table '%s.%s' doesn't exist
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl.go:442: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl.go:451: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:1336: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/ddl.go:102: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/ddl.go:74: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/adapter.go:182: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/tidb.go:172: 
{
  "currDBName": "da",
  "id": 103,
  "status": 2,
  "strictMode": true,
  "user": "[email protected]"
}
2017/08/04 00:53:34 conn.go:377: [warning] [103] dispatch error:
id:103, addr:10.56.1.106:43506 status:2, collation:utf8_general_ci, user:da
TRUNCATE `schema_migrations`
[schema:1146]Table '%s.%s' doesn't exist
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl.go:442: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl.go:451: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/ddl/ddl_api.go:1336: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/ddl.go:102: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/ddl.go:74: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/adapter.go:182: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/tidb.go:172: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/session.go:625: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/server/conn.go:681:
Kansuler picture Kansuler on 4 Aug 2017

@shenli

breeswish picture breeswish on 4 Aug 2017

@breeswish @Kansuler In TiDB, DDL jobs will run in sequence one by one. So in this case, truncate table will be converted into two jobs, one is drop table, another one is create table with the same name and schema. So if the sequence is DropTable, AlterTable, CreateTable, then the AlterTable will found not table with that name.
It is indeed a problem, but not a serious one. We will handle this in the future.

shenli picture shenli on 4 Aug 2017
👍3
Was this page helpful?
0 / 5 - 0 ratings

Related issues

thinktainer picture thinktainer  路  3Comments
leoppro picture leoppro  路  4Comments
Lvnszn picture Lvnszn  路  3Comments
ekexium picture ekexium  路  3Comments
zz-jason picture zz-jason  路  3Comments