最近有一个接口偶然出现超时报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”,获得本文最新内容。