背景
事情的情况大致是这样的。一个扣减库存的业务上线以后,隔几天会报一次错,错误内容如下:
ERROR - exception: UncategorizedSQLException,"detail":"org.springframework.jdbc.UncategorizedSQLException:
### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLQueryInterruptedException: Query execution was interrupted
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: UPDATE a SET stock = stock - ? WHERE id = ? and stock >= ?
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLQueryInterruptedException: Query execution was interrupted
; uncategorized SQLException for SQL []; SQL state [70100]; error code [1317]; Query execution was interrupted; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLQueryInterruptedException: Query execution was interrupted
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:84)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
at com.sun.proxy.$Proxy64.update(null:-1)
at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:62)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
这块业务之前一直都是正常的,迁移以后做的唯一大的改动就是加了java事务注解,所以怀疑是否和事务有关。
排查过程
首先现寻找报错的关键信息,第一个看到的是UncategorizedSQLException。查看这个类的源代码,说明如下:
/**
* Exception thrown when we can't classify a SQLException into
* one of our generic data access exceptions.
*
* @author Rod Johnson
* @author Juergen Hoeller
*/
可以看到,这个类是Spring无法归类的一个SQL异常,所以从这个异常我们是看不出什么内容的,继续往下。
MySQLQueryInterruptedException: Query execution was interrupted
发现这个执行是超时被kill了。一般来讲,我们公司dba设置的mysql超时时间是500ms。是否是因为数据量太大,没有走到索引,才导致update操作执行时间太长被kill了呢?看一下update语句里
UPDATE a SET stock = stock - ? WHERE id = ? and stock >= ?
马上排除了这个可能性。因为where条件里有id查询,必定会走主键索引,不可能没有走到索引。那会是什么原因呢?
上面我们提到,这个业务操作里是开启了事务的,还原一下大体的执行情况。
start transaction;
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1;
INSERT INTO a (num) values (1);
commit;
查了一下当时的日志,发现1秒内有大约200条请求对一条记录做更新库存的操作。
线索渐渐清晰起来了,事故现场大致应该是这样的:
T1 | T2 |
---|---|
begin | begin |
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1; | |
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1; | |
INSERT INTO a (num) values (1); | |
T2执行完成,1 rows affected | |
T1 Query execution was interrupted |
结论
由于开启了事务,在高并发地对一条记录进行更新的情况下,多个请求会进入排队系统。由于锁的竞争是不公平的,当多个事务同时对一条记录进行更新时,极端情况下,就可能会出现一个更新操作进去排队系统以后,一直拿不到锁,超过500ms被kill了。
细节分析
以上的业务操作,update会先申请行锁,拿到行锁以后进行更新,更新完以后会执行插入操作。那么在插入操作的时候是否需要申请锁呢?
答案是肯定的,不过这里的插入操作使用的是自增锁。那自增锁是什么级别的锁呢?
如果存在自增字段,MySQL会维护一个自增锁,和自增锁相关的一个参数为(5.1.22版本之后加入)
innodb_autoinc_lock_mode:可以设定3个值,0,1,2
0:traditonal (每次都会产生表锁)
1:consecutive (会产生一个轻量锁,simple insert会获得批量的锁,保证连续插入)
2:interleaved (不会锁表,来一个处理一个,并发最高)
Myisam引擎均为traditional,InnoDB默认为1,轻量锁。所以在InnoDB的情况下,这里的insert操作的性能比update操作更高。
优化
有了以上结论以后,那如何优化呢?
最简单的方案就是减少持有锁的时间,处理方式非常简单,将更新操作放到最后执行,从而缩短更新锁的持有时间,避免类似的超时问题。
start transaction;
INSERT INTO a (num) values (1);
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1;
commit;
参考资料:
业务优化案例一则
mysql并发insert死锁问题——gap、插入意向锁冲突
InnoDB并发插入,居然使用意向锁?
MySQL自增锁