MySQL锁超时问题分析

自己项目中由于业务快速迭代,代码质量堪忧,随着客户量的增长,生产环境上出现许多锁超时的问题. 本篇文章记录一下自己排查锁超时的过程与总结.

问题初现

最近生产环境频繁收到 Lock wait timeout exceeded 的告警邮件.

org.springframework.dao.CannotAcquireLockException: 
### Error updating database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
### The error may involve com.best.qianyi.dao.inventory.SkuInventoryDao.allocate-Inline
### The error occurred while setting parameters
### SQL: UPDATE    ge_sku_inventory    SET   update_time = NOW(6),   allocated = allocated + ?   WHERE id = ?   AND customer_id = ?   AND allocated + ? >= 0   AND allocated + ? <= total    AND is_deleted = 0
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:262)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
    at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:74)
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:421)
    at com.sun.proxy.$Proxy155.update(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:270)
    ...

DB环境确定

收到告警邮件之后便思考这个问题出现的原因是什么?
首先先确定一个参数,锁等待多久会超时?当前DB竟然锁超时时间是50秒.

SHOW VARIABLES LIKE 'innodb_lock_wait_timeout';

问题分析

再回到看这个SQL,根据主键ID去扣减库存. 从业务上来分析,库存扣减确实是频繁操作,涉及到的业务有很多,而生产抛出异常的这个业务确只是受害者而已.真正的罪魁祸首还在逍遥法外...

UPDATE    ge_sku_inventory    SET   update_time = NOW(6),   allocated = allocated + ?   WHERE id = ?   AND customer_id = ?   AND allocated + ? >= 0   AND allocated + ? <= total    AND is_deleted = 0

再看这个SQL其实只会锁1行，那么罪魁祸首肯定也是跟这一行的业务相关的操作，这时就两个猜想了。

猜想1 这个时间段有大量的跟这个业务相关的操作，导致行锁一直被其他业务事务占用，当前业务线程获取不到锁资源，导致超时。
猜想2 有大事务占用，大事务持有锁时间超过50S，导致其余线程无法获取X锁。

确认方向

有了两个猜想之后，便想办法去确认是哪种情况。

验证猜想1

1 可以去翻生成日志，检查报错前50S是否有大量更新业务的操作。
2 通过SQL审计功能去检查这个时间段是否有大量更新这一行的SQL。
在这个问题上验证之后发现不可能，相关请求很少。

验证猜想2

生产环境DB用的是RDS服务，可以在利用RDS提供的SQL审计功能，去查询出在报错前1,2分钟，对这一行做的更新SQL，于此同时可查询出对应的MYSQL线程ID，然后根据线程ID查询完整的事务，得知其事务开始时间及结束时间，最后发现确实有一个3分钟左右的大事务，到这儿就定位到罪魁祸首的事务了。

定位代码

根据上面的事务我们可以去找到对应的业务代码，根据各SQL执行的开始时间，很容易定位到耗时代码的区间，最后发现造成大事务的原因是，在DB事务中有请求第三方接口的需求，因为接口不稳定，导致长时间占用X锁，严重影响了其他业务。解决方案就是拆请求，尽量保证第三方接口交互与DB事务隔离开来。

如果大家有其他思路，可以留言讨论哦，学无止境，互相交流，不删库跑路。