replace into 引发的异常

【TiDB 版本】:

3.0.5

【与此问题相关的资料】:

异常:TxnLockNotFound 引发的原因:

这个报错是因为第一个事务一直没有提交,在等待一定时间之后后面的事务会清理掉之前事务的锁信息,等到第一个事务再去提交的时候发现锁没了,就会报错 TxnLockNotFound

【问题描述】:

使用**REPLACE INTO**批量插入数据, 刚开始插入数据时,没有问题,虽着数据量的增多,出现了如下问题:

  1. [WARN] [pd.go:109] [“get timestamp too slow”]
  2. [WARN] [session.go:446] [“commit failed”] [conn=67956] [“finished txn”=“Txn{state=invalid}”]
  3. [WARN] [session.go:964] [“run statement error”] [conn=67956] [schemaVersion=11638]
  4. [error="[executor:5]BatchInsert failed with error:
  5. [error="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound

详情请看 tidb.log

tidb.log

[2020/01/06 09:14:17.831 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:527.478167ms txnStartTS:413734864303685633 region_id:45309 store_addr:192.168.180.52:20160 kv_process_ms:487 scan_total_write:0 scan_processed_write:0 scan_total_data:0 scan_processed_data:0 scan_total_lock:0 scan_processed_lock:0"]
[2020/01/06 09:14:17.995 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=tx_read_only] [val=0]
[2020/01/06 09:14:17.995 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:18.035 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=tx_read_only] [val=1]
[2020/01/06 09:14:18.035 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=transaction_read_only] [val=1]
[2020/01/06 09:14:18.358 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:473.771127ms txnStartTS:413734864303685633 region_id:45309 store_addr:192.168.180.52:20160 kv_process_ms:441 scan_total_write:0 scan_processed_write:0 scan_total_data:0 scan_processed_data:0 scan_total_lock:0 scan_processed_lock:0"]
[2020/01/06 09:14:18.464 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=33.398166ms]
[2020/01/06 09:14:18.464 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=33.418478ms]
[2020/01/06 09:14:18.720 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:516.293349ms txnStartTS:413734864972152837 region_id:43958 store_addr:192.168.180.52:20160"]
[2020/01/06 09:14:18.720 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:11.667046254s txnStartTS:413734862062354433 region_id:42622 store_addr:192.168.180.52:20160"]
[2020/01/06 09:14:18.720 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:5.141018788s txnStartTS:413734863766290433 region_id:43958 store_addr:192.168.180.52:20160"]
[2020/01/06 09:14:18.720 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:12.94245714s txnStartTS:413734861590495236 region_id:45309 store_addr:192.168.180.52:20160 kv_process_ms:457 scan_total_write:248397 scan_processed_write:229394 scan_total_data:248351 scan_processed_data:229394 scan_total_lock:6 scan_processed_lock:0"]
[2020/01/06 09:14:18.748 +08:00] [WARN] [session.go:446] ["commit failed"] [conn=67956] ["finished txn"="Txn{state=invalid}"] [error="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413734862848786436, commit_ts: 413734865129439233, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 51, 49, 52, 53, 51, 100, 52, 56, 255, 57, 102, 101, 51, 52, 50, 97, 50, 255, 56, 57, 100, 55, 53, 51, 56, 99, 255, 98, 57, 56, 101, 53, 98, 53, 52, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]"]
[2020/01/06 09:14:18.748 +08:00] [INFO] [tidb.go:169] ["rollbackTxn for ddl/autocommit error."]

[2020/01/06 09:14:18.758 +08:00] [WARN] [session.go:964] ["run statement error"] [conn=67956] [schemaVersion=11638] [error="[executor:5]BatchInsert failed with error: [kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413734862848786436, commit_ts: 413734865129439233, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 51, 49, 52, 53, 51, 100, 52, 56, 255, 57, 102, 101, 51, 52, 50, 97, 50, 255, 56, 57, 100, 55, 53, 51, 56, 99, 255, 98, 57, 56, 101, 53, 98, 53, 52, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]"]
 [errorVerbose="[executor:5]BatchInsert failed with error: [kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413734862848786436, commit_ts: 413734865129439233, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 51, 49, 52, 53, 51, 100, 52, 56, 255, 57, 102, 101, 51, 52, 50, 97, 50, 255, 56, 57, 100, 55, 53, 51, 56, 99, 255, 98, 57, 56, 101, 53, 98, 53, 52, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]
github.com/pingcap/errors.AddStack
        github.com/pingcap/errors@v0.11.4/errors.go:174
github.com/pingcap/parser/terror.(*Error).GenWithStack
        github.com/pingcap/parser@v0.0.0-20191018040038-555b97093a2a/terror/terror.go:231
github.com/pingcap/tidb/executor.(*InsertValues).doBatchInsert
        github.com/pingcap/tidb@/executor/insert_common.go:368
github.com/pingcap/tidb/executor.(*InsertValues).insertRows
        github.com/pingcap/tidb@/executor/insert_common.go:213
github.com/pingcap/tidb/executor.(*ReplaceExec).Next
        github.com/pingcap/tidb@/executor/replace.go:194
github.com/pingcap/tidb/executor.Next
        github.com/pingcap/tidb@/executor/executor.go:191
github.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor
        github.com/pingcap/tidb@/executor/adapter.go:431
github.com/pingcap/tidb/executor.(*ExecStmt).Exec
        github.com/pingcap/tidb@/executor/adapter.go:295
github.com/pingcap/tidb/session.runStmt
        github.com/pingcap/tidb@/session/tidb.go:238
github.com/pingcap/tidb/session.(*session).executeStatement
        github.com/pingcap/tidb@/session/session.go:961
github.com/pingcap/tidb/session.(*session).execute
        github.com/pingcap/tidb@/session/session.go:1076
github.com/pingcap/tidb/session.(*session).Execute
        github.com/pingcap/tidb@/session/session.go:999
github.com/pingcap/tidb/server.(*TiDBContext).Execute
        github.com/pingcap/tidb@/server/driver_tidb.go:246
github.com/pingcap/tidb/server.(*clientConn).handleQuery
        github.com/pingcap/tidb@/server/conn.go:1195
github.com/pingcap/tidb/server.(*clientConn).dispatch
        github.com/pingcap/tidb@/server/conn.go:913
github.com/pingcap/tidb/server.(*clientConn).Run
        github.com/pingcap/tidb@/server/conn.go:666
github.com/pingcap/tidb/server.(*Server).onConn
        github.com/pingcap/tidb@/server/server.go:440
runtime.goexit
        runtime/asm_amd64.s:1357"] [session="{
  \"currDBName\": \"pressure_pfizer\",
  \"id\": 67956,
  \"status\": 2,
  \"strictMode\": true,
  \"user\": {
    \"Username\": \"root\",
    \"Hostname\": \"192.168.181.55\",
    \"CurrentUser\": false,
    \"AuthUsername\": \"root\",
    \"AuthHostname\": \"%\"
  }
}"]

[2020/01/06 09:14:18.759 +08:00] [WARN] [conn.go:682] ["dispatch error"] [conn=67956] [connInfo="id:67956, addr:192.168.181.55:37374 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] 
[sql="replace into dc_table_1(a,b,c,.............,paas_id) values 
('DI00007963',null,null,'DI00007963','烟台毓璜顶医院','HO00001522',null,null,'115965','********','10502',25,25,null,null,null,'1',null,null,null,'null','2019-12-30 00:00:00','1',null,845.null,null,342.0,8561.0,null,null,'烟台市********','1mg*14片',null,'000010','AX9640',null,'0','后台接口','2020-01-06 09:13:50.718','后台接口','2020-01-06 09:13:50.718',null,'0','151bcb3d5b724025bc5c51fb37372787')
,('DI00007963',null,null,'DI00007963','济宁新华********有限公司','DS0074183',null,null,'115965','********','10502',5,5,null,null,null,'1',null,null,null,'null','2019-12-30 00:00:00','1',null,829.null,null,342.0,1712.0,null,null,'山东省济宁市********','1mg*14片',null,'000020','AX9640',null,'0','后台接口','2020-01-06 09:13:50.718','后台接口','2020-01-06 09:13:50.718',null,'0','27c1ba4933eb486ca9d688b549cc29c0')
,('DI00007963',null,null,'DI00007963','济宁********','HO00024124',null,null,'115967','********','10502',1,1,null,null,null,'1',null,null,null,'null','2019-12-30 00:00:00','1',null,5796,null,342.null,342.null,null,null,'济宁市市中********','34rfd',null,'000010','********',null,'0','后台接口','2020-01-06 09:13:50.718','后台接口','2020-01-06 09:13:50.718',null,'0','c4bf2d8a661e4a0a9456c5bc9d1c9388')
,('DI00007963',null,null,'DI00007963','山东大学********','HO00001404',null,null,'115967','********','10502',18,18,null,null,null,'1',null,null,null,'null','2019-12-30 00:00:00','1',null,5796,null,342.null,6164.0,null,null,'济南市********','asdf',null,'000010','********',null,'0','后台接口','2020-01-06 09:13:50.718','后台接口','2020-01-06 09:13:50.718',null,'0','1979b25f3c484b1caf37cb7f4d0bfb8f')
,('DI00007963',null,null,'DI00007963','华润德州********','DI00015380',null,null,'115967','********','10502',10,10,null,null,null,'1',null,null,null,'null','2019-12-30 00:00:00','1',null,5553.0,null,342.0,3424.0,null,null,'山东省德州市********','asdf',null,'000010','********',null,'0','后>台接口','2020-01-06 09:13:50.718','后台接口','2020-01-06 09:1(len: 720114)"]
[err="[executor:5]BatchInsert failed with error: [kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413734862848786436, commit_ts: 413734865129439233, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 51, 49, 52, 53, 51, 100, 52, 56, 255, 57, 102, 101, 51, 52, 50, 97, 50, 255, 56, 57, 100, 55, 53, 51, 56, 99, 255, 98, 57, 56, 101, 53, 98, 53, 52, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]

github.com/pingcap/errors.AddStack
        github.com/pingcap/errors@v0.11.4/errors.go:174
github.com/pingcap/parser/terror.(*Error).GenWithStack
        github.com/pingcap/parser@v0.0.0-20191018040038-555b97093a2a/terror/terror.go:231
github.com/pingcap/tidb/executor.(*InsertValues).doBatchInsert
        github.com/pingcap/tidb@/executor/insert_common.go:368
github.com/pingcap/tidb/executor.(*InsertValues).insertRows
        github.com/pingcap/tidb@/executor/insert_common.go:213
github.com/pingcap/tidb/executor.(*ReplaceExec).Next
        github.com/pingcap/tidb@/executor/replace.go:194
github.com/pingcap/tidb/executor.Next
        github.com/pingcap/tidb@/executor/executor.go:191
github.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor
        github.com/pingcap/tidb@/executor/adapter.go:431
github.com/pingcap/tidb/executor.(*ExecStmt).Exec
        github.com/pingcap/tidb@/executor/adapter.go:295
github.com/pingcap/tidb/session.runStmt
        github.com/pingcap/tidb@/session/tidb.go:238
github.com/pingcap/tidb/session.(*session).executeStatement
        github.com/pingcap/tidb@/session/session.go:961
github.com/pingcap/tidb/session.(*session).execute
        github.com/pingcap/tidb@/session/session.go:1076
github.com/pingcap/tidb/session.(*session).Execute
        github.com/pingcap/tidb@/session/session.go:999
github.com/pingcap/tidb/server.(*TiDBContext).Execute
        github.com/pingcap/tidb@/server/driver_tidb.go:246
github.com/pingcap/tidb/server.(*clientConn).handleQuery
        github.com/pingcap/tidb@/server/conn.go:1195
github.com/pingcap/tidb/server.(*clientConn).dispatch
        github.com/pingcap/tidb@/server/conn.go:913
github.com/pingcap/tidb/server.(*clientConn).Run
        github.com/pingcap/tidb@/server/conn.go:666
github.com/pingcap/tidb/server.(*Server).onConn
        github.com/pingcap/tidb@/server/server.go:440
runtime.goexit
        runtime/asm_amd64.s:1357"]

[2020/01/06 09:14:18.783 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=67956] [txnStartTS=413734862848786436]
[2020/01/06 09:14:18.830 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=tx_read_only] [val=0]
[2020/01/06 09:14:18.830 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:18.854 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=tx_read_only] [val=1]
[2020/01/06 09:14:18.854 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67960] [name=transaction_read_only] [val=1]
[2020/01/06 09:14:19.069 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=0]
[2020/01/06 09:14:19.069 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:19.103 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=1]
[2020/01/06 09:14:19.103 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=1]
[2020/01/06 09:14:19.104 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67977] [name=tx_read_only] [val=1]
[2020/01/06 09:14:19.104 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67977] [name=transaction_read_only] [val=1]
[2020/01/06 09:14:19.392 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=0]
[2020/01/06 09:14:19.392 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67977] [name=tx_read_only] [val=0]
[2020/01/06 09:14:19.392 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:19.392 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67977] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:19.420 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=1]
[2020/01/06 09:14:19.420 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=1]
[2020/01/06 09:14:19.473 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=51.675798ms]
[2020/01/06 09:14:19.473 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=42.0153ms]
[2020/01/06 09:14:19.473 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=42.024573ms]
[2020/01/06 09:14:19.784 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=0]
[2020/01/06 09:14:19.784 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=0]
[2020/01/06 09:14:19.814 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=tx_read_only] [val=1]
[2020/01/06 09:14:19.814 +08:00] [INFO] [set.go:192] ["set session var"] [conn=67968] [name=transaction_read_only] [val=1]

上面的资料中说明了是因为事务的冲突和select超时,但是我是向一张空表中插入数据,为什么也会有这样的问题呢?

【我期望的】:

  1. 这个异常的引发原因
  2. 如何避免这样的问题发生
  3. 这个异常对数据的影响
  1. 这个异常的引发原因
  • 根据你的描述,可能是大事务执行写入导致的 TxnLock 被 gc 清理掉。
  1. 如何避免这样的问题发生
  • 拆解成小事务
  • 调整 gc 时间和 max-txn-time 时间
  1. 这个异常对数据的影响
  • 没有影响,如果已经报错给客户端,根据报错判断重新执行即可。