最近有一个接口偶然出现超时报500的情况，通过服务后台log，发现以下错误，说白了就是在更新mysql的时候，获取排它锁超时导致更新失败了。
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.dao.CannotAcquireLockException: PreparedStatementCallback; SQL [UPDATE news SET news.quality = ? WHERE news.pk = ?]; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
exception的堆栈如下：
这是什么原因呢？我在想，会不会是代码在同一个事务里面有死锁的情况，于是查看了代码，发现代码使用的是spring“声明式”事务，该接口的业务层面不会发生死锁的情况。
于是我想，会不会是和其他的事务有交叉加锁而导致死锁呢？于是通过mysql的“show engine innodb status;”语句把最近的死锁信息copy出来检查了一遍，发现最近的“LATEST DETECTED DEADLOCK”的相关数据里面并没有和news表相关的dead lock，那说明可能不是死锁导致的。
于是我想着去服务器看下报错的那个时间附近有没有相关的慢查询，通过耗时和时间过滤，一看，果然，报错的附近时间刚好有一个很慢的慢查询，如下图最后一行，耗时达到了57s，扫描了六千多万行记录，吓我一跳，如下图：
上图的第一行，就是报错接口业务层执行的更新语句，说明接口在更新mysql的时候，等待了51s，还没竞争到锁，所以失败了。但是那个慢查询是select类型的语句，根据mysql的mvvc乐观锁，不应该锁表才对啊，于是猜测可能是同一个事物里面，包含了update的语句以及该慢查询。这个事务先是update news表，这时候锁住相关记录，然后再执行这个慢查询，等慢查询结束之后，才释放锁，那就说明确实是这个慢查询的长事务导致的。于是根据这个sql的来源ip，原来是大数据团队的sql，通过大数据团队的确认，确实是猜想的那样，有个长事务，在同一个事务里面，先是update了news表，然后执行了上面的慢查询。于是让大数据团队赶紧优化sql，优化sql之后，持续跟踪了一段时间，发现这个问题不在出现。
这里还有一个小问题，上面的报错接口业务执行的update语句，为什么是持续竞争锁51s之后，就报错了呢？mysql的innodb引擎是有个事务锁超时的时间的，通过以下语句可以查到：
# 查询全局等待事务锁超时时间 SHOW GLOBAL VARIABLES LIKE ‘innodb_lock_wait_timeout‘; ? # 查询当前会话等待事务锁超时时间 SHOW VARIABLES LIKE ‘innodb_lock_wait_timeout‘;
通过查询，mysql服务器的事务锁超时时间刚好是50s，如下，和上面实际获取锁超时51s相差了1s，可能是有一定的误差的吧。
innodb_lock_wait_timeout 50
谢谢观赏~
欢迎关注微信公众号“ismallboy”，请扫码并关注以下公众号，并在公众号下面回复“lock”，获得本文最新内容。