Lock wait timeout exceeded; Connection com.mysql.jdbc.JDBC4Connection@a53e67 marked as broken

1、Lock wait timeout exceeded; try restarting transaction

异常如下：

2019-12-05 18:24:56.037  WARN 8856 --- [nio-8080-exec-2] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 1205, SQLState: 40001
2019-12-05 18:24:56.038 ERROR 8856 --- [nio-8080-exec-2] o.h.engine.jdbc.spi.SqlExceptionHelper   : Lock wait timeout exceeded; try restarting transaction
2019-12-05 18:24:56.042  WARN 8856 --- [nio-8080-exec-2] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Warning Code: 1205, SQLState: 40001
2019-12-05 18:24:56.042  WARN 8856 --- [nio-8080-exec-2] o.h.engine.jdbc.spi.SqlExceptionHelper   : Lock wait timeout exceeded; try restarting transaction
org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:250)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:225)
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:436)
    at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
    at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:213)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:131)
    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.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
    at com.sun.proxy.$Proxy162.updateContainerRunning(Unknown Source)

 

从异常看，是锁等待超时造成的，查看mysql的timeout设置：

mysql> show global variables like '%timeout%';
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| connect_timeout             | 10       |
| delayed_insert_timeout      | 300      |
| have_statement_timeout      | YES      |
| innodb_flush_log_at_timeout | 1        |
| innodb_lock_wait_timeout    | 50       |
| innodb_rollback_on_timeout  | OFF      |
| interactive_timeout         | 28800    |
| lock_wait_timeout           | 31536000 |
| net_read_timeout            | 30       |
| net_write_timeout           | 60       |
| rpl_stop_slave_timeout      | 31536000 |
| slave_net_timeout           | 60       |
| wait_timeout                | 28800    |
+-----------------------------+----------+
13 rows in set (0.01 sec)

由于 innodb_lock_wait_timeout默认是50s，即等待超过50s后，mysql会报错：ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

可见，应该是由于该条记录被锁定了（事务还未提交），因此需要查询出该事务所等待的那个线程的id，如: 73904，然后kill掉即可。

mysql> select * from information_schema.innodb_trx \G;
*************************** 1. row ***************************
                    trx_id: 104748
                 trx_state: LOCK WAIT
               trx_started: 2019-12-05 18:21:18
     trx_requested_lock_id: 104748:129:3:2
          trx_wait_started: 2019-12-05 18:21:18
                trx_weight: 2
       trx_mysql_thread_id: 73905
                 trx_query: update testset status='01' where id = 376
       trx_operation_state: starting index read
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 2. row ***************************
                    trx_id: 104747
                 trx_state: RUNNING
               trx_started: 2019-12-05 18:21:13
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 3
       trx_mysql_thread_id: 73904
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 1
         trx_rows_modified: 1
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
2 rows in set (0.01 sec)

ERROR: 
No query specified

mysql> select * from information_schema.INNODB_LOCKS;
+----------------+-------------+-----------+-----------+-----------------------+------------+------------+-----------+----------+-----------+
| lock_id        | lock_trx_id | lock_mode | lock_type | lock_table            | lock_index | lock_space | lock_page | lock_rec | lock_data |
+----------------+-------------+-----------+-----------+-----------------------+------------+------------+-----------+----------+-----------+
| 104748:129:3:2 | 104748      | X         | RECORD    | `tx_test`.`test` | PRIMARY    |        129 |         3 |        2 | 376       |
| 104747:129:3:2 | 104747      | X         | RECORD    | `tx_test`.`test` | PRIMARY    |        129 |         3 |        2 | 376       |
+----------------+-------------+-----------+-----------+-----------------------+------------+------------+-----------+----------+-----------+
2 rows in set, 1 warning (0.00 sec)

mysql> select * from information_schema.INNODB_LOCK_WAITS;
+-------------------+-------------------+-----------------+------------------+
| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id |
+-------------------+-------------------+-----------------+------------------+
| 104748            | 104748:129:3:2    | 104747          | 104747:129:3:2   |
+-------------------+-------------------+-----------------+------------------+
1 row in set, 1 warning (0.00 sec)
 

 

如果kill掉当前线程，即：73905，则会报错：

2019-12-05 18:30:56.623  WARN 8856 --- [nio-8080-exec-4] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@25526958 marked as broken because of SQLSTATE(08S01), ErrorCode(0)

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 50,596 milliseconds ago.  The last packet sent successfully to the server was 50,594 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
    at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1284)
    at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:785)
    at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073)
    at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2009)
    at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5098)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1994)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208)
    at org.hibernate.engine.query.spi.NativeSQLQueryPlan.performExecuteUpdate(NativeSQLQueryPlan.java:211)
    at org.hibernate.internal.SessionImpl.executeNativeUpdate(SessionImpl.java:1346)
    at org.hibernate.internal.SQLQueryImpl.executeUpdate(SQLQueryImpl.java:389)
    at org.hibernate.jpa.internal.QueryImpl.internalExecuteUpdate(QueryImpl.java:371)
    at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:78)
    at org.springframework.data.jpa.repository.query.JpaQueryExecution$ModifyingExecution.doExecute(JpaQueryExecution.java:238)
    at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:78)
    at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:100)
    at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:91)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:462)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:440)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:61)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:131)
    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.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
    at com.sun.proxy.$Proxy162.updateContainerRunning(Unknown Source)
    at com.test.service.TestService.txTest1(TestService.java:423)

org.springframework.dao.DataAccessResourceFailureException: could not execute statement; nested exception is org.hibernate.exception.JDBCConnectionException: could not execute statement
2019-12-05 18:30:56.625  WARN 8856 --- [nio-8080-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08S01
2019-12-05 18:30:56.625 DEBUG 8856 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@25526958: (connection is broken)
2019-12-05 18:30:56.625 ERROR 8856 --- [nio-8080-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : Communications link failure

The last packet successfully received from the server was 50,596 milliseconds ago.  The last packet sent successfully to the server was 50,594 milliseconds ago.
2019-12-05 18:30:56.628 DEBUG 8856 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@25526958 failed

 

如果kill掉73904（即：如果连接池中的一个连接被kill掉），也会报错：

2019-12-05 19:27:55.678  WARN 14756 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@409f6149 marked as broken because of SQLSTATE(08007), ErrorCode(0)

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link failure during commit(). Transaction resolution unknown.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
    at com.mysql.jdbc.Util.getInstance(Util.java:387)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:917)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
    at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1618)
    at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:368)
    at com.zaxxer.hikari.pool.HikariProxyConnection.commit(HikariProxyConnection.java)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:112)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:180)
    at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:77)
    at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
    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:485)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)

 

 

2019-12-05 19:27:55.683  INFO 14756 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection com.mysql.jdbc.JDBC4Connection@409f6149 on thread http-nio-8080-exec-1 was returned to the pool (unleaked)
2019-12-05 19:27:55.685 DEBUG 14756 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@409f6149: (connection is broken)
2019-12-05 19:27:55.686 DEBUG 14756 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.mysql.jdbc.JDBC4Connection@409f6149 failed

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
    at com.mysql.jdbc.Util.getInstance(Util.java:387)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:917)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
    at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1246)
    at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1241)
    at com.mysql.jdbc.ConnectionImpl.setNetworkTimeout(ConnectionImpl.java:5521)
    at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:541)
    at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:129)
    at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:434)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 75,005 milliseconds ago.  The last packet sent successfully to the server was 2 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
    at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1614)
    at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:368)
    at com.zaxxer.hikari.pool.HikariProxyConnection.commit(HikariProxyConnection.java)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doCommit(JdbcTransaction.java:112)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:180)
    at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:77)
    at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
    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:485)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)