异常 KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound

mao_siyu · 2019 年11 月 20 日 06:56

TiKV

单机多节点
1单机 - 3kv

【TiDB 版本】：

3.0.5

【问题描述】：

数据导入时TiKV发生如下异常

tikv.log

[2019/11/20 13:52:15.698 +08:00] [INFO] [gc_worker.rs:336] ["unsafe destroy range finished deleting files in range"] [cost_time=19.414µs] [end_key=748000000000000BFFE300000000000000F8] [start_key=748000000000000BFFE200000000000000F8]
[2019/11/20 13:52:15.698 +08:00] [INFO] [gc_worker.rs:374] ["unsafe destroy range finished cleaning up all"] [cost_time=448.412µs] [end_key=748000000000000BFFE300000000000000F8] [start_key=748000000000000BFFE200000000000000F8]
[2019/11/20 13:52:16.986 +08:00] [ERROR] [endpoint.rs:454] [error-response] [err="locked primary_lock: 7480000000000000135F6980000000000000010405BA1D792280000303800000000001065A lock_version: 412674722397421570 key: 7480000000000000175F69800000000000000103800000000000151903800000000000000003800000000000000C038000000000000000 lock_ttl: 3588 txn_size: 456"]
[2019/11/20 13:52:17.044 +08:00] [ERROR] [endpoint.rs:454] [error-response] [err="locked primary_lock: 7480000000000000135F6980000000000000010405BA1D792280000303800000000001065A lock_version: 412674722397421570 key: 7480000000000000175F69800000000000000103800000000000151903800000000000000003800000000000000C038000000000000000 lock_ttl: 3588 txn_size: 456"]
[2019/11/20 13:52:17.205 +08:00] [ERROR] [endpoint.rs:454] [error-response] [err="locked primary_lock: 7480000000000000135F6980000000000000010405BA1D792280000303800000000001065A lock_version: 412674722397421570 key: 7480000000000000175F69800000000000000103800000000000151903800000000000000003800000000000000C038000000000000000 lock_ttl: 3588 txn_size: 456"]
[2019/11/20 13:52:17.235 +08:00] [INFO] [gc_worker.rs:300] ["unsafe destroy range started"] [end_key=748000000000000BFFE500000000000000F8] [start_key=748000000000000BFFE400000000000000F8]
[2019/11/20 13:52:17.236 +08:00] [INFO] [gc_worker.rs:336] ["unsafe destroy range finished deleting files in range"] [cost_time=21.239µs] [end_key=748000000000000BFFE500000000000000F8] [start_key=748000000000000BFFE400000000000000F8]
[2019/11/20 13:52:17.286 +08:00] [INFO] [gc_worker.rs:374] ["unsafe destroy range finished cleaning up all"] [cost_time=50.123469ms] [end_key=748000000000000BFFE500000000000000F8] [start_key=748000000000000BFFE400000000000000F8]

tidb.log

[2019/11/20 13:52:17.516 +08:00] [WARN] [session.go:655] [sql] [conn=98941] [label=general] ["retry reached max count"=10]
[2019/11/20 13:52:17.516 +08:00] [WARN] [session.go:446] ["commit failed"] [conn=98941] ["finished txn"="Txn{state=invalid}"] [error="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 412674721584775214, commit_ts: 412674723013459978, key: [116, 128, 0, 0, 0, 0, 0, 7, 182, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 97, 54, 48, 50, 51, 97, 50, 102, 255, 45, 48, 98, 53, 57, 45, 49, 49, 255, 101, 97, 45, 98, 101, 100, 52, 45, 255, 102, 97, 98, 49, 101, 101, 101, 98, 255, 57, 52, 97, 97, 0, 0, 0, 0, 251] })) [try again later]"]
[2019/11/20 13:52:17.516 +08:00] [WARN] [session.go:964] ["run statement error"] [conn=98941] [schemaVersion=5243] [error="previous statement: "INSERT INTO ACT_RU_VARIABLE .................,ff"(len:13162)"] [session="{
  "currDBName": "dev2_pfizer_activiti",
  "id": 98941,
  "status": 0,
  "strictMode": true,
  "user": {
    "Username": "root",
    "Hostname": "192.168.230.113",
    "CurrentUser": false,
    "AuthUsername": "root",
    "AuthHostname": "%"
  }
}"]
[2019/11/20 13:52:17.516 +08:00] [WARN] [conn.go:682] ["dispatch error"] [conn=98941] [connInfo="id:98941, addr:192.168.230.113:59316 status:0, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:0"] [sql=commit] [err="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 412674721584775214, commit_ts: 412674723013459978, key: [116, 128, 0, 0, 0, 0, 0, 7, 182, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 97, 54, 48, 50, 51, 97, 50, 102, 255, 45, 48, 98, 53, 57, 45, 49, 49, 255, 101, 97, 45, 98, 101, 100, 52, 45, 255, 102, 97, 98, 49, 101, 101, 101, 98, 255, 57, 52, 97, 97, 0, 0, 0, 0, 251] })) [try again later]
previous statement: "INSERT INTO ACT_RU_VARIABLE .......................,ff"(len:13162)"]
[2019/11/20 13:52:17.633 +08:00] [INFO] [set.go:192] ["set session var"] [conn=99379] [name=tx_read_only] [val=1]
[2019/11/20 13:52:17.633 +08:00] [INFO] [set.go:192] ["set session var"] [conn=99379] [name=transaction_read_only] [val=1]
[2019/11/20 13:52:17.644 +08:00] [INFO] [set.go:192] ["set session var"] [conn=99379] [name=tx_read_only] [val=0]

ACT_RU_VARIABLE 表结构

CREATE TABLE `ACT_RU_VARIABLE` (
  `ID_` varchar(64) NOT NULL,
  `REV_` int(11) DEFAULT NULL,
  `TYPE_` varchar(255) NOT NULL,
  `NAME_` varchar(255) NOT NULL,
  `EXECUTION_ID_` varchar(64) DEFAULT NULL,
  `PROC_INST_ID_` varchar(64) DEFAULT NULL,
  `TASK_ID_` varchar(64) DEFAULT NULL,
  `BYTEARRAY_ID_` varchar(64) DEFAULT NULL,
  `DOUBLE_` double DEFAULT NULL,
  `LONG_` bigint(20) DEFAULT NULL,
  `TEXT_` varchar(4000) DEFAULT NULL,
  `TEXT2_` varchar(4000) DEFAULT NULL,
  PRIMARY KEY (`ID_`),
  KEY `ACT_IDX_VARIABLE_TASK_ID` (`TASK_ID_`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin;

zzzzzz · 2019 年11 月 20 日 07:05

可能是行冲突导致的锁清理，重试事务应该可以恢复正常。

mao_siyu · 2019 年11 月 20 日 07:15

老师你好我如果想定位这个问题，在grafana上面应该查看哪些模块，去查看哪些监控数据

zzzzzz · 2019 年11 月 20 日 07:18

可以看下 overview -> tidb -> lock resolve ops | kv backoff ops

mao_siyu · 2019 年11 月 20 日 07:25

zzzzzz · 2019 年11 月 20 日 07:35

监控中可以看到当时有比较多的 region 调度造成了 region miss 同时有 tikvlockfast 的锁存在。不过数量看起来比较健康。

这边这个报错的频率高么？

mao_siyu · 2019 年11 月 20 日 07:37

出现的概率很低的，当时我在迁移数据库，然后同事并不知道我在大量的写数据，要写入的数据量大概在4G左右，他也上传大文件，在这种不知情的情况下，才出了这个问题。

GangShen · 2019 年11 月 20 日 14:11

可以尝试根据 tidb.log 中的 start_ts 以及 commit_ts 在 tidb.log 以及慢日志中查找一下，看能否找到对应冲突的事务，可以看下是什么 SQL 冲突了

mao_siyu · 2020 年1 月 16 日 06:48

你好老师，这个问题最近又出现了，在大量插入数据时出现的

目前TiDB 已经改成了全局的悲观锁模式

v3.0.5

java 程序异常

Caused by: java.sql.SQLException: Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: […] })) [try again later]

20-01-16 11:06:54 TraceId:[] [SimpleAsyncTaskExecutor-1] WARN  o.s.a.r.l.ConditionalRejectingErrorHandler - Execution of Rabbit message listener failed.
org.springframework.amqp.rabbit.listener.exception.ListenerExecutionFailedException: Listener threw exception
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.wrapToListenerExecutionFailedExceptionIfNeeded(AbstractMessageListenerContainer.java:941)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:851)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:771)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$001(SimpleMessageListenerContainer.java:102)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$1.invokeListener(SimpleMessageListenerContainer.java:198)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.invokeListener(SimpleMessageListenerContainer.java:1311)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:752)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:1254)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:1224)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$1600(SimpleMessageListenerContainer.java:102)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1470)
	at java.lang.Thread.run(Thread.java:745)
Caused by: org.springframework.transaction.TransactionSystemException: Could not commit Hibernate transaction; nested exception is org.hibernate.TransactionException: commit failed
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:588)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:518)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
	at com.sinoeyes.db.service.pfizer.DcFlowdataDeliverSaleManager$$EnhancerBySpringCGLIB$$ee57639f.saveDcFlowdataDeliverSale(<generated>)
	at com.sinoeyes.mapping.service.SourceToFinalService.transferEdiSale(SourceToFinalService.java:493)
	at com.sinoeyes.mapping.service.SourceToFinalService.invokeTransfer(SourceToFinalService.java:278)
	at com.sinoeyes.mapping.service.SourceToFinalService.lambda$transferData2Final$0(SourceToFinalService.java:114)
	at java.util.ArrayList.forEach(ArrayList.java:1249)
	at com.sinoeyes.mapping.service.SourceToFinalService.transferData2Final(SourceToFinalService.java:106)
	at com.sinoeyes.mapping.service.SourceToFinalService$$FastClassBySpringCGLIB$$8a43d1f6.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
	at com.sinoeyes.log.annotation.TuningMonitorLogger.aroundAdvisor(TuningMonitorLogger.java:77)
	at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
	at com.sinoeyes.mapping.service.SourceToFinalService$$EnhancerBySpringCGLIB$$fe3ed9b2.transferData2Final(<generated>)
	at com.sinoeyes.mapping.listener.CheckAllPending2FinalListener.onMessage(CheckAllPending2FinalListener.java:41)
	at com.sinoeyes.mapping.listener.CheckAllPending2FinalListener.onMessage(CheckAllPending2FinalListener.java:18)
	at com.sinoeyes.jms.AbstractQueueMessageReceiver$1.onMessage(AbstractQueueMessageReceiver.java:84)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:848)
	... 10 common frames omitted
Caused by: org.hibernate.TransactionException: commit failed
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:187)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
	... 46 common frames omitted
Caused by: org.hibernate.TransactionException: unable to commit against JDBC connection
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:116)
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:180)
	... 47 common frames omitted
Caused by: java.sql.SQLException: Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 99, 55, 50, 255, 54, 102, 97, 99, 51, 56, 97, 55, 255, 48, 49, 54, 102, 97, 99, 53, 48, 255, 57, 51, 100, 50, 50, 49, 53, 53, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:964)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2483)
	at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1548)
	at com.alibaba.druid.pool.DruidPooledConnection.commit(DruidPooledConnection.java:749)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:112)
	... 48 common frames omitted
	



















20-01-16 10:49:29 TraceId:[] [SimpleAsyncTaskExecutor-1] WARN  o.s.a.r.l.ConditionalRejectingErrorHandler - Execution of Rabbit message listener failed.
org.springframework.amqp.rabbit.listener.exception.ListenerExecutionFailedException: Listener threw exception
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.wrapToListenerExecutionFailedExceptionIfNeeded(AbstractMessageListenerContainer.java:941)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:851)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:771)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$001(SimpleMessageListenerContainer.java:102)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$1.invokeListener(SimpleMessageListenerContainer.java:198)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.invokeListener(SimpleMessageListenerContainer.java:1311)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:752)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:1254)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:1224)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$1600(SimpleMessageListenerContainer.java:102)
	at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1470)
	at java.lang.Thread.run(Thread.java:745)
Caused by: org.springframework.transaction.TransactionSystemException: Could not commit Hibernate transaction; nested exception is org.hibernate.TransactionException: commit failed
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:588)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:518)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
	at com.sinoeyes.db.service.pfizer.DcFlowdataDeliverSaleManager$$EnhancerBySpringCGLIB$$bec7121e.saveDcFlowdataDeliverSale(<generated>)
	at com.sinoeyes.mapping.service.SourceToFinalService.transferEdiSale(SourceToFinalService.java:493)
	at com.sinoeyes.mapping.service.SourceToFinalService.invokeTransfer(SourceToFinalService.java:278)
	at com.sinoeyes.mapping.service.SourceToFinalService.lambda$transferData2Final$0(SourceToFinalService.java:114)
	at java.util.ArrayList.forEach(ArrayList.java:1249)
	at com.sinoeyes.mapping.service.SourceToFinalService.transferData2Final(SourceToFinalService.java:106)
	at com.sinoeyes.mapping.service.SourceToFinalService$$FastClassBySpringCGLIB$$8a43d1f6.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
	at com.sinoeyes.log.annotation.TuningMonitorLogger.aroundAdvisor(TuningMonitorLogger.java:77)
	at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
	at com.sinoeyes.mapping.service.SourceToFinalService$$EnhancerBySpringCGLIB$$2c540f63.transferData2Final(<generated>)
	at com.sinoeyes.mapping.listener.CheckAllPending2FinalListener.onMessage(CheckAllPending2FinalListener.java:41)
	at com.sinoeyes.mapping.listener.CheckAllPending2FinalListener.onMessage(CheckAllPending2FinalListener.java:18)
	at com.sinoeyes.jms.AbstractQueueMessageReceiver$1.onMessage(AbstractQueueMessageReceiver.java:84)
	at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:848)
	... 10 common frames omitted
Caused by: org.hibernate.TransactionException: commit failed
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:187)
	at org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:584)
	... 46 common frames omitted
Caused by: org.hibernate.TransactionException: unable to commit against JDBC connection
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:116)
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:180)
	... 47 common frames omitted
Caused by: java.sql.SQLException: Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413962849663057923, commit_ts: 413962854552043522, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 55, 57, 55, 255, 54, 102, 97, 99, 51, 56, 55, 52, 255, 48, 49, 54, 102, 97, 99, 52, 49, 255, 50, 102, 49, 48, 48, 99, 55, 50, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:964)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2483)
	at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1548)
	at com.alibaba.druid.pool.DruidPooledConnection.commit(DruidPooledConnection.java:749)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:112)
	... 48 common frames omitted

tidb.log


[2020/01/16 11:06:54.650 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:26.194490676s txnStartTS:413963121702993925 region_id:89025 store_addr:172.106.180.53:20160 kv_process_ms:216 scan_total_write:198304 scan_processed_write:132680 scan_total_data:198155 scan_processed_data:132680 scan_total_lock:1 scan_processed_lock:0"]
[2020/01/16 11:06:54.650 +08:00] [INFO] [region_cache.go:287] ["invalidate current region, because others failed on same store"] [region=40] [store=172.106.180.53:20160]
[2020/01/16 11:06:54.656 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:5.770516127s txnStartTS:413963113956638724 region_id:89377 store_addr:172.106.180.53:20160"]
[2020/01/16 11:06:54.658 +08:00] [WARN] [session.go:446] ["commit failed"] [conn=22869] ["finished txn"="Txn{state=invalid}"] [error="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 99, 55, 50, 255, 54, 102, 97, 99, 51, 56, 97, 55, 255, 48, 49, 54, 102, 97, 99, 53, 48, 255, 57, 51, 100, 50, 50, 49, 53, 53, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]"]
[2020/01/16 11:06:54.658 +08:00] [WARN] [session.go:964] ["run statement error"] [conn=22869] [schemaVersion=14017] [error="previous statement: /*......*/  insert into dc_fds (..............) values (..........): [kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 99, 55, 50, 255, 54, 102, 97, 99, 51, 56, 97, 55, 255, 48, 49, 54, 102, 97, 99, 53, 48, 255, 57, 51, 100, 50, 50, 49, 53, 53, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]"] [errorVerbose="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 99, 55, 50, 255, 54, 102, 97, 99, 51, 56, 97, 55, 255, 48, 49, 54, 102, 97, 99, 53, 48, 255, 57, 51, 100, 50, 50, 49, 53, 53, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]\
previous statement: /*......*/  insert into dc_fds (.......) values (......)"] [session="{\
  \"currDBName\": \"pressure_pf\",\
  \"id\": 22869,\
  \"status\": 0,\
  \"strictMode\": true,\
  \"user\": {\
    \"Username\": \"root\",\
    \"Hostname\": \"172.106.181.51\",\
    \"CurrentUser\": false,\
    \"AuthUsername\": \"root\",\
    \"AuthHostname\": \"%\"\
  }\
}"]
[2020/01/16 11:06:54.659 +08:00] [WARN] [conn.go:682] ["dispatch error"] [conn=22869] [connInfo="id:22869, addr:172.160.181.51:47446 status:0, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:0"] [sql=commit] [err="[kv:6]Error: KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound { start_ts: 413963114113925133, commit_ts: 413963128571166725, key: [116, 128, 0, 0, 0, 0, 0, 52, 197, 95, 105, 128, 0, 0, 0, 0, 0, 0, 1, 1, 56, 97, 55, 52, 56, 99, 55, 50, 255, 54, 102, 97, 99, 51, 56, 97, 55, 255, 48, 49, 54, 102, 97, 99, 53, 48, 255, 57, 51, 100, 50, 50, 49, 53, 53, 255, 0, 0, 0, 0, 0, 0, 0, 0, 247] })) [try again later]\
previous statement: /*......*/  insert into dc_fds (.......) values (.......)"]
[2020/01/16 11:06:54.660 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:554.768763ms txnStartTS:413963128426987525 region_id:89045 store_addr:172.160.180.59:20160 kv_process_ms:554 scan_total_write:137280 scan_processed_write:137279 scan_total_data:137279 scan_processed_data:137279 scan_total_lock:1 scan_processed_lock:0"]
[2020/01/16 11:06:54.672 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:4.465431012s txnStartTS:413963113956638724 region_id:89377 store_addr:172.160.180.53:20160"]
[2020/01/16 11:06:54.673 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:5.625270458s txnStartTS:413963113956638724 region_id:136647 store_addr:172.160.180.53:20160"]
[2020/01/16 11:06:54.673 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:5.421161595s txnStartTS:413963113956638724 region_id:136647 store_addr:172.160.180.53:20160"]

监控图表

GangShen · 2020 年1 月 16 日 08:54

TxnLockNotFound

这个是事务提交的慢了，超过了 TTL 被其他事务给 Rollback 掉了。
事务 ttl 默认是 3s
乐观和悲观在提交阶段都可能有这个报错
通过 key 查对应的行可以用 https://github.com/disksing/mok

mao_siyu · 2020 年1 月 16 日 09:28

谢谢老师，请问默认 TTL 时间可以改吗？怎么改呢？

GangShen · 2020 年1 月 16 日 09:49

目前这个是在代码中写死的，不支持修改

github.com

pingcap/tidb/blob/master/store/tikv/lock_resolver.go#L124




// IsCommitted returns true if the txn's final status is Commit.
func (s TxnStatus) IsCommitted() bool { return s.ttl == 0 && s.commitTS > 0 }


// CommitTS returns the txn's commitTS. It is valid iff `IsCommitted` is true.
func (s TxnStatus) CommitTS() uint64 { return uint64(s.commitTS) }


// By default, locks after 3000ms is considered unusual (the client created the
// lock might be dead). Other client may cleanup this kind of lock.
// For locks created recently, we will do backoff and retry.
var defaultLockTTL uint64 = 3000


// TODO: Consider if it's appropriate.
var maxLockTTL uint64 = 120000


// ttl = ttlFactor * sqrt(writeSizeInMiB)
var ttlFactor = 6000


// Lock represents a lock from tikv server.
type Lock struct {
	Key      []byte

mao_siyu · 2020 年1 月 16 日 09:50

好的知道啦谢谢老师

GangShen · 2020 年1 月 16 日 09:52

不客气~

Hacker_chu · 2020 年6 月 29 日 10:03

意思是，如果一个事务超过3秒没有commit的话，系统会自动 Rollback 掉吗？

zuok · 2021 年4 月 26 日 06:12

系统自动 Rollback 掉的话，程序中会有日志打印吗?,我现在是测试环境会捕捉到异常抛出，但是生产上并没有任何的错误抛出，可是数据在flink任务跑了几天之后会莫名其妙的丢。

system · 2022 年10 月 31 日 19:11

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。

异常 KV error safe to retry tikv restarts txn: Txn(Mvcc(TxnLockNotFound

TiKV

【TiDB 版本】：

【问题描述】：

tikv.log

tidb.log

ACT_RU_VARIABLE 表结构

你好老师，这个问题最近又出现了，在大量插入数据时出现的

目前TiDB 已经改成了 全局的悲观锁模式

v3.0.5

java 程序 异常

tidb.log

监控图表

目前TiDB 已经改成了全局的悲观锁模式

java 程序异常