前言
最近线上业务在运行过程中，遇到如下异常：
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表
各字段含义
java代码解读复制代码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表
各字段含义
java代码解读复制代码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表
各字段含义
java代码解读复制代码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（当前线程详情）进行分析及处理。具体步骤如下：
重点关注：trx_id(事务id)、trx_state(事务状态)、trx_started(事务开始时间)、trx_mysql_thread_id(对应的线程id)、trx_query(执行的语句)
重点关注：lock_trx_id(阻塞事务的id)、lock_table(锁住的表)、lock_data(锁定行的主键)
重点关注：blocking_trx_id(阻塞事务的id)
select * from information_schema.innodb_lock_waits;找出相互等待的事务
select * from information_schema.innodb_locks;查看各事务锁的相关数据
select * from information_schema.innodb_trx;获取当前正在运行的事务详情
show full processlist;获取当前各线程详情，辅助定位问题
识别出造成锁等待的事务对应的线程id后，用kill id;命令将对应的线程kill掉即可
