# [KB]关于 TiDB 同一时刻对同一张表truncate执行逻辑混乱,服务器报错  information schema is changed during the execution of the statement

## Issue

在处理一次 JOB 跑不成功的过程中，发现存在部署两台应用同一个时间点跑 JOB 该 JOB 中含有 Truncate table 操作，出现 truncate DDL 操作相互影响情况，始终会有一个 DDL 失败的问题！

### DDL 日志记录

1. IP16--tidb.log 日志中，`2021/03/26 00:00:02.983 +08:00` 时间戳运行日志， conn=187340 从 IP16 的会话在start time: 2021-03-26 00:00:02.949 +0800 CST 执行了 `truncate table vsComStatus`。 日志信息如下：

    ```log
    \[2021/03/2600:00:02.983 +08:00]\[INFO]\[session.go:2161]\["CRUCIAL OPERATION"]\[conn=187340]\[schemaVersion=4733]\[cur_db=test]\[sql=" truncate table XXX_table_name"]\[user=XXX_dbuser@xxx.xxx.xxx.xxx]\[2021/03/2600:00:02.991 +08:00]\[INFO]\[ddl.go:487]\["\[ddl] start DDL job"]\[job="ID:7849, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, 
    ArgLen:1, start time:2021-03-2600:00:02.949 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]\[query=" truncate table XXX_table_name"]\[2021/03/2600:00:02.977 +08:00]\[INFO]\[coprocessor.go:934]\["\[TIME_COP_PROCESS] resp_time:733.955944ms txnStartTS:423805059648454677 region_id:543643 store_addr:xxx.xxx.xxx.xxx:20160 kv_process_ms:732 scan_total_write:179092 scan_processed_write:179091 scan_total_data:98205 scan_processed_data:98205 scan_total_lock:1 scan_processed_lock:0"]\[conn=187340]\[2021/03/2600:00:02.983 +08:00]\[INFO]\[session.go:2161]\["CRUCIAL OPERATION"]\[conn=187340]\[schemaVersion=4733]\[cur_db=test]\[sql=" truncate table XXX_table_name"]\[user=XXX_dbuser@xxx.xxx.xxx.xxx]]
    ```

2. IP15--tidb.log 日志中，2021/03/26 00:00:03.374 +08:00 时间戳行日志。conn=206842 从IP15的会话，在start time: 2021-03-26 00:00:03.349 +0800 CST 执行了truncate table XXX_table_name 日志信息如下：

    ```log
    \[2021/03/2600:00:03.374 +08:00]\[INFO]\[session.go:2161]\["CRUCIAL OPERATION"]\[conn=206842]\[schemaVersion=4733]\[cur_db=test]\[sql=" truncate table XXX_table_name"]\[user=XXX_dbuser@xxx.xxx.xxx.xxx]]\[2021/03/2600:00:03.374 +08:00]\[INFO]\[session.go:1441]\["NewTxn() inside a transaction auto commit"]\[conn=206842]\[schemaVersion=4733]\[txnStartTS=423805059766419467]\[2021/03/2600:00:03.381 +08:00]\[INFO]\[ddl_worker.go:261]\["\[ddl] add DDL jobs"]\["batch count"=1]\[jobs="ID:7851, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:1, start time: 2021-03-26 00:00:03.349 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
    ```

3. IP15--tidb.log 日志中,2021/03/26 00:00:03.467 +08:00 出现关键报错： Information schema is changed ...... try increasing tidb_max_delta_schema_count,tidb.log 结果报错如下：

    ```
    \[tidb@ip-9-23-3-15 log]$ grep "conn=206842"tidb.log\[2021/03/2600:00:03.372 +08:00]\[INFO]\[coprocessor.go:934]\["\[TIME_COP_PROCESS] resp_time:700.496984ms txnStartTS:423805059766419467 region_id:543643 store_addr:xxx.xxx.xxx.xxx:20160 kv_process_ms:698 scan_total_write:179092 scan_processed_write:179091 scan_total_data:98205 scan_processed_data:98205 scan_total_lock:1 scan_processed_lock:0"]\[conn=206842]\[2021/03/2600:00:03.374 +08:00]\[INFO]\[session.go:2161]\["CRUCIAL OPERATION"]\[conn=206842]\[schemaVersion=4733]\[cur_db=test]\[sql=" truncate table XXX_table_name"]\[user=XXX_dbuser@xxx.xxx.xxx.xxx]]\[2021/03/2600:00:03.374 +08:00]\[INFO]\[session.go:1441]\["NewTxn() inside a transaction auto commit"]\[conn=206842]\[schemaVersion=4733]\[txnStartTS=423805059766419467]\[2021/03/2600:00:03.467 +08:00]\[WARN]\[session.go:1066]\["run statement failed"]\[conn=206842]\[schemaVersion=4733]\[error="\[domain:8028]Information schema is changed during the execution of the statement(for example, table definition may be updated by other DDL ran in parallel). If you see this error often, try increasing `tidb_max_delta_schema_count`. \[try again later]"]\[session="{\n \"currDBName\": \"test\",\n \"id\":206842,\n \"preparedStmtCount\":36,\n \"status\":0,\n \"strictMode\":true,\n \"user\":{\n \"Username\": \"XXX_dbuser\",\n \"Hostname\": \"xxx.xxx.xxx.xxx]\",\n \"CurrentUser\":false,\n \"AuthUsername\": \"XXX_dbuser\",\n \"AuthHostname\": \"%\"\n }
    \n}"]\[2021/03/2600:00:03.467 +08:00]\[INFO]\[conn.go:787]\["command dispatched failed"]\[conn=206842]\[connInfo="id:206842, addr:xxx.xxx.xxx.xxx]:37486 status:0, collation:utf8_general_ci, user:XXX_dbuser"]\[command=Query]\[status="inTxn:0, autocommit:0"]\[sql=" truncate table XXX_table_name"]\[txn_mode=PESSIMISTIC]\[err="[domain:8028]Information schema is changed during the execution of the statement(for example, table definition may be updated by other DDL ran in parallel). If you see this error often, try increasing `tidb_max_delta_schema_count`. [try again later]\ngithub.com/pingcap/errors.AddStack\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20200917111840-a15ef68f753d/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20200917111840-a15ef68f753d/juju_adaptor.go:15\ngithub.com/pingcap/tidb/executor.(\*DDLExec).toErr\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/ddl.go:64\ngithub.com/pingcap/tidb/executor.(\*DDLExec).Next\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/ddl.go:132\ngithub.com/pingcap/tidb/executor.Next\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/executor.go:253\ngithub.com/pingcap/tidb/executor.(\*ExecStmt).handleNoDelayExecutor\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/adapter.go:516\ngithub.com/pingcap/tidb/executor.(\*ExecStmt).handlePessimisticDML\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/adapter.go:535\ngithub.com/pingcap/tidb/executor.(\*ExecStmt).handleNoDelay\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/adapter.go:396\ngithub.com/pingcap/tidb/executor.(\*ExecStmt).Exec\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/executor/adapter.go:354\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/session/tidb.go:286\ngithub.com/pingcap/tidb/session.(\*session).executeStatement\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/session/session.go:1063\ngithub.com/pingcap/tidb/session.(\*session).execute\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/session/session.go:1175\ngithub.com/pingcap/tidb/session.(\*session).Execute\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/session/session.go:1106\ngithub.com/pingcap/tidb/server.(\*TiDBContext).Execute\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/server/driver_tidb.go:248\ngithub.com/pingcap/tidb/server.(\*clientConn).handleQuery\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/server/conn.go:1354\ngithub.com/pingcap/tidb/server.(\*clientConn).dispatch\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/server/conn.go:985\ngithub.com/pingcap/tidb/server.(\*clientConn).Run\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/server/conn.go:772\ngithub.com/pingcap/tidb/server.(\*Server).onConn\n\t/home/jenkins/agent/workspace/tidb_v4.0.8/go/src/github.com/pingcap/tidb/server/server.go:421\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357"]
    ```

4. 如下日志中间部分所展示当两个session同时truncate执行的时候会出现相互影响，job=ID:7849 在经历了add->start>run->finish之后，table版本已经改变。此时另一个truncate执行时，却出现\["\[ddl] DDL job is cancelled normally"] \[worker="worker 1, tp general"] \[error="\[schema:1146]Table '(Schema ID 5163).(Table ID 7844)' doesn't exist"]，报错版本不存在，

    ```log
    \[2021/03/26 00:00:03.374 +08:00] \[INFO] \[session.go:1441] \["NewTxn() inside a transaction auto commit"] \[conn=206842] \[schemaVersion=4733] \[txnStartTS=423805059766419467]
    \[2021/03/26 00:00:03.381 +08:00] \[INFO] \[ddl_worker.go:261] \["\[ddl] add DDL jobs"] \["batch count"=1] \[jobs="ID:7851, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:1, start time: 2021-03-26 00:00:03.349 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
    \[2021/03/26 00:00:03.381 +08:00] \[INFO] \[ddl.go:487] \["\[ddl] start DDL job"] \[job="ID:7851, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:1, start time: 2021-03-26 00:00:03.349 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] \[query=" truncate table XXX_table_name"]
    \[2021/03/26 00:00:03.383 +08:00] \[INFO] \[ddl_worker.go:588] \["\[ddl] run DDL job"] \[worker="worker 1, tp general"] \[job="ID:7849, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:0, start time: 2021-03-26 00:00:02.949 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
    \[2021/03/26 00:00:03.400 +08:00] \[INFO] \[domain.go:127] \["diff load InfoSchema success"] \[usedSchemaVersion=4733] \[neededSchemaVersion=4734] \["start time"=1.467892ms] \[phyTblIDs="\[7844,7848]"] \[actionTypes="\[2048,2048]"]
    \[2021/03/26 00:00:03.449 +08:00] \[INFO] \[ddl_worker.go:777] \["\[ddl] wait latest schema version changed"] \[worker="worker 1, tp general"] \[ver=4734] \["take time"=51.844685ms] \[job="ID:7849, Type:truncate table, State:done, SchemaState:public, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:2, start time: 2021-03-26 00:00:02.949 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
    \[2021/03/26 00:00:03.451 +08:00] \[INFO] \[delete_range.go:350] \["\[ddl] insert into delete-range table"] \[jobID=7849] \[elementID=7844]
    \[2021/03/26 00:00:03.456 +08:00] \[INFO] \[delete_range.go:105] \["\[ddl] add job into delete-range table"] \[jobID=7849] \[jobType="truncate table"]
    \[2021/03/26 00:00:03.457 +08:00] \[INFO] \[ddl_worker.go:367] \["\[ddl] finish DDL job"] \[worker="worker 1, tp general"] \[job="ID:7849, Type:truncate table, State:synced, SchemaState:public, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:2, start time: 2021-03-26 00:00:02.949 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
    \[2021/03/26 00:00:03.462 +08:00] \[INFO] \[ddl_worker.go:588] \["\[ddl] run DDL job"] \[worker="worker 1, tp general"] \[job="ID:7851, Type:truncate table, State:none, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:0, start time: 2021-03-26 00:00:03.349 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
    \[2021/03/26 00:00:03.462 +08:00] \[INFO] \[ddl_worker.go:687] \["\[ddl] DDL job is cancelled normally"] \[worker="worker 1, tp general"] \[error="\[schema:1146]Table '(Schema ID 5163).(Table ID 7844)' doesn't exist"]
    \[2021/03/26 00:00:03.463 +08:00] \[INFO] \[ddl_worker.go:367] \["\[ddl] finish DDL job"] \[worker="worker 1, tp general"] \[job="ID:7851, Type:truncate table, State:cancelled, SchemaState:none, SchemaID:5163, TableID:7844, RowCount:0, ArgLen:1, start time: 2021-03-26 00:00:03.349 +0800 CST, Err:\[schema:1146]Table '(Schema ID 5163).(Table ID 7844)' doesn't exist, ErrCount:1, SnapshotVersion:0"]
    \[2021/03/26 00:00:03.466 +08:00] \[INFO] \[schema_validator.go:232] \["the related physical table ID is empty"] \[schemaVer=4733] \[latestSchemaVer=4734]
    \[2021/03/26 00:00:03.466 +08:00] \[INFO] \[tidb.go:218] \["rollbackTxn for ddl/autocommit failed"]
    \[2021/03/26 00:00:03.467 +08:00] \[WARN] \[session.go:1066] \["run statement failed"] \[conn=206842] \[schemaVersion=4733] \[error="\[domain:8028]Information schema is changed during the execution of the statement(for example, table definition may be updated by other DDL ran in parallel). If you see this error often, try increasing `tidb_max_delta_schema_count`. \[try again later]"] \[session="{\n \"currDBName\": \"test\",\n \"id\": 206842,\n \"preparedStmtCount\": 36,\n \"status\": 0,\n \"strictMode\": true,\n \"user\":
    {\n \"Username\": \"XXX_dbuser\",\n \"Hostname\": \"xxx.xxx.xxx.xxx]\",\n \"CurrentUser\": false,\n \"AuthUsername\": \"XXX_dbuser\",\n \"AuthHostname\": \"%\"\n }
    \n}"]
    ```

## Root Cause

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.

相关问题的 issue：[https://github.com/pingcap/tidb/issues/3876](https://github.com/pingcap/tidb/issues/3876)

## Diagnostic Steps

1. 查看 tidb.log 日志存在报错 information schema is changed during the execution of the statement

2. 查看 tidb.log 日志存在 (Table ID 7844)' doesn't exist

3. 查看业务存在两个及以上的 job 同时运行 truncate table 操作。

## Resolution

这是 TiDB DDL 机制的已知缺陷，暂未修复。