问题

最近线上业务在运行过程中，遇到如下异常：

2021-01-13 10:25:20.838 WARN [http-nio-7010-exec-104][SqlExceptionHelper.java:127] - SQL Error: 1205, SQLState: 41000

2021-01-13 10:25:20.839 INFO [http-nio-7010-exec-104][AbstractBatchImpl.java:193] - HHH000010: On release of batch it still contained JDBC statements

2021-01-13 10:25:20.839 ERROR [http-nio-7010-exec-104][SqlExceptionHelper.java:129] - Lock wait timeout exceeded; try restarting transaction

Stack trace:

org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockTimeoutException: could not execute statement

...

Caused by: org.hibernate.exception.LockTimeoutException: could not execute statement

at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:520)

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:95)

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207)

at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3134)

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3013)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3393)

at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:582)

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:456)

at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)

at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)

at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282)

at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:465)

at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2963)

at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2339)

at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:485)

at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:147)

at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)

at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)

at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:65)

at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:61)

at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)

... 181 more

Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1084)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4232)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4164)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2843)

at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:166)

at sun.reflect.GeneratedMethodAccessor366.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at com.mysql.jdbc.LoadBalancingConnectionProxy.invoke(LoadBalancingConnectionProxy.java:651)

at com.mysql.jdbc.LoadBalancingConnectionProxy.invoke(LoadBalancingConnectionProxy.java:556)

at com.sun.proxy.$Proxy212.execSQL(Unknown Source)

at com.mysql.fabric.jdbc.FabricMySQLConnectionProxy.execSQL(FabricMySQLConnectionProxy.java:961)

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2085)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2337)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2265)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2249)

at sun.reflect.GeneratedMethodAccessor369.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)

at com.sun.proxy.$Proxy465.executeUpdate(Unknown Source)

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)

... 201 more

复制代码

业务场景：发布某些特定的资源，发现一直在等待，直到超时抛出异常

问题定位过程

从异常堆栈来看，问题的根源在于Lock wait timeout exceeded; try restarting transaction异常。从异常信息来看，应该是：mysql锁超时了

刚开始的时候，认为是大资源导致操作的sql较多，从而达到设置的最大超时时间。尝试在测试、预生产模拟该类大资源，但数据能正常审核。通过sql语句(如下)检查各环境innodb_lock_wait_timeout的值，发现都是50s。结合pinpoint上的调用链可发现，整个事务的执行时间大概4s左右，但事务一直没提交，直到超时。所以基本上可以排除掉该业务本身导致的超时

SHOW VARIABLES LIKE 'innodb_lock_wait_timeout';

复制代码

排除了业务本身的超时可能性后，基本上可以确认是两个事务之间，锁等待导致的超时。因为锁等待是mysql抛出的异常，第一反应是mysql是否提供了锁等待的相关详情用于辅助定位问题。经过百度、google发现mysql的information_schema确实有几个表(innodb_trx、innodb_locks、innodb_lock_waits)来存储锁的相关信息可用于定位问题

# 锁等待的对应关系

select * from information_schema.innodb_lock_waits;

# 当前出现的锁

select * from information_schema.innodb_locks;

# 当前运行的所有事务

select * from information_schema.innodb_trx;

# 当前线程详情

show full processlist;

复制代码

经过与DBA的配合,在生产复现了该问题,拿到了相关数据。通过对数据的分析可以看到，确实是一个事务在等待另一个事务释放锁，另一个事务持有了一个资源的资源，导致另一个事务一直等待到超时。并且通过trx_started可发现，持有锁的事务是一天前开启的，还没释放。

从上面的数据分析来看，是：昨天开启的一个事务导致的，该事务对应的线程数为20154145，该线程id对应的info为null，user为业务正常使用的账号。考虑到业务上都是使用@Transactional注解来声明事务,按理说,spring应该会正常管理事务进行commit和rollback。所以定位到此，还是没找到根本原因

想着如果是某个业务导致的，服务重启之后，mysql连接断掉之后，应该就会正常。因此，对服务进行了重启

重启之后，发现该问题还是存在，资源还是无法发布。因此重新找DBA拿了相关数据。分析数据可以发现，持有锁的事务id变了，原先的那个事务不见了，但新启了一个事务，该事务持有了锁，导致了后续业务无法正常拿到锁。并且，该事务的开始时间基本上在服务重启的一小会。所以应该是存在什么业务会去开启一个新事务，并且一直不commit

结合业务场景，想了很久还是无法想到有什么业务会导致这种情况。因此只能让DBA先把持有锁的事务kill掉

这时候出现了一个很神奇的事情，当DBA把线程kill掉之后，有个MQ发送了消费异常的告警消息。至此造成锁等待超时的元凶算是找到了

进一步分析这个MQ的消费可以发现：该MQ会开启一个事务，在事务中，会取到被影响到的所有资源(大约1w多)，然后for循环对相关资源进行联动操作。所以造成了事务开启后，一直无法提交

mysql锁相关表详解

innodb_lock_waits表

requesting_trx_id：请求事务的ID

requested_lock_id：请求事务的锁ID。可以和 INNODB_LOCKS 表 JOIN

blocking_trx_id：阻塞事务的 ID

blocking_lock_id：阻塞事务的锁ID。可以和 INNODB_LOCKS 表 JOIN

复制代码

innodb_locks表

lock_id：锁id

lock_trx_id：拥有锁的事务ID。可以和 INNODB_TRX 表 JOIN 得到事务的详细信息

lock_mode：锁的模式。有如下锁类型：行级锁包括：S、X、IS、IX，分别代表：共享锁、排它锁、意向共享锁、意向排它锁。表级锁包括：S_GAP、X_GAP、IS_GAP、IX_GAP 和 AUTO_INC，分别代表共享间隙锁、排它间隙锁、意向共享间隙锁、意向排它间隙锁和自动递增锁。

lock_type：锁的类型。RECORD 代表行级锁，TABLE 代表表级锁。

lock_table：被锁定的或者包含锁定记录的表的名称。

lock_index：当lock_table='RECORD' 时，表示索引的名称；否则为 NULL。

lock_space：当lock_table='RECORD' 时，表示锁定行的表空间ID；否则为 NULL。

lock_page：当lock_table='RECORD' 时，表示锁定行的页号；否则为 NULL。

lock_rec：当lock_table='RECORD'时，表示一堆页面中锁定行的数量，亦即被锁定的记录号；否则为 NULL。

lock_data：当lock_table='RECORD' 时，表示锁定行的主键；否则为NULL

复制代码

innodb_trx表

trx_id：事务ID

trx_state：事务状态，有以下几种状态：RUNNING、LOCK WAIT、ROLLING BACK 和 COMMITTING

trx_started：事务开始时间

trx_requested_lock_id：事务当前正在等待锁的标识，可以和 INNODB_LOCKS 表 JOIN 以得到更多详细信息

trx_wait_started：事务开始等待的时间

trx_weight：事务的权重

trx_mysql_thread_id：事务线程 ID，可以和 PROCESSLIST 表 JOIN。

trx_query：事务正在执行的 SQL 语句。

trx_operation_state：事务当前操作状态。

trx_tables_in_use：当前事务执行的 SQL 中使用的表的个数。

trx_tables_locked：当前执行 SQL 的行锁数量。

trx_lock_structs：事务保留的锁数量。

trx_lock_memory_bytes：事务锁住的内存大小，单位为 BYTES。

trx_rows_locked：事务锁住的记录数。包含标记为 DELETED，并且已经保存到磁盘但对事务不可见的行。

trx_rows_modified：事务更改的行数。

trx_concurrency_tickets：事务并发票数。

trx_isolation_level：当前事务的隔离级别。

trx_unique_checks：是否打开唯一性检查的标识。

trx_foreign_key_checks：是否打开外键检查的标识。

trx_last_foreign_key_error：最后一次的外键错误信息。

trx_adaptive_hash_latched：自适应散列索引是否被当前事务锁住的标识。

trx_adaptive_hash_timeout：是否立刻放弃为自适应散列索引搜索 LATCH 的标识

复制代码

processlist表

Id：连接标识符。可通过kill id将该线程kill掉

User：访问的用户

Host：发出该语句的客户端的主机名。格式：host_name:client_port

db：线程的默认数据库。如果未选择任何数据库，则为null

Command: 线程代表客户端执行的命令类型。如果会话处于空闲状态，则为Sleep。该列的值对应于客户端/服务器协议的 命令和 状态变量

Time：线程处于其当前状态的时间(以秒为单位)

State：指示线程正在执行的操作，事件或状态

Info：线程正在执行的语句。如果线程不执行任何语句，则为null

复制代码

结论

开发业务的时候要注意：尽量不要有长事务，长事务很容易造成锁竞争

遇到 Lock wait timeout exceeded 异常时，可结合 innodb_lock_waits(锁等待的对应关系)、innodb_locks(当前出现的锁)、innodb_trx(当前运行的所有事务)、show full processlist(当前线程详情)进行分析及处理。具体步骤如下：

select * from information_schema.innodb_lock_waits;找出相互等待的事务

重点关注：blocking_trx_id(阻塞事务的id)

select * from information_schema.innodb_locks;查看各事务锁的相关数据

重点关注：lock_trx_id(阻塞事务的id)、lock_table(锁住的表)、lock_data(锁定行的主键)

select * from information_schema.innodb_trx;获取当前正在运行的事务详情

重点关注：trx_id(事务id)、trx_state(事务状态)、trx_started(事务开始时间)、trx_mysql_thread_id(对应的线程id)、trx_query(执行的语句)

show full processlist;获取当前各线程详情，辅助定位问题

识别出造成锁等待的事务对应的线程id后，用kill id;命令将对应的线程kill掉即可

参考链接