背景

事情的情況大致是這樣的。一個(gè)扣減庫(kù)存的業(yè)務(wù)上線以后，隔幾天會(huì)報(bào)一次錯(cuò)，錯(cuò)誤內(nèi)容如下：

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)

這塊業(yè)務(wù)之前一直都是正常的，遷移以后做的唯一大的改動(dòng)就是加了java事務(wù)注解，所以懷疑是否和事務(wù)有關(guān)。

排查過(guò)程

首先現(xiàn)尋找報(bào)錯(cuò)的關(guān)鍵信息，第一個(gè)看到的是UncategorizedSQLException。查看這個(gè)類(lèi)的源代碼，說(shuō)明如下：

/**
 * Exception thrown when we can't classify a SQLException into
 * one of our generic data access exceptions.
 *
 * @author Rod Johnson
 * @author Juergen Hoeller
 */

可以看到，這個(gè)類(lèi)是Spring無(wú)法歸類(lèi)的一個(gè)SQL異常，所以從這個(gè)異常我們是看不出什么內(nèi)容的，繼續(xù)往下。

MySQLQueryInterruptedException: Query execution was interrupted

發(fā)現(xiàn)這個(gè)執(zhí)行是超時(shí)被kill了。一般來(lái)講，我們公司dba設(shè)置的mysql超時(shí)時(shí)間是500ms。是否是因?yàn)閿?shù)據(jù)量太大，沒(méi)有走到索引，才導(dǎo)致update操作執(zhí)行時(shí)間太長(zhǎng)被kill了呢？看一下update語(yǔ)句里

UPDATE a SET stock = stock - ? WHERE id = ? and stock >= ?

馬上排除了這個(gè)可能性。因?yàn)閣here條件里有id查詢(xún)，必定會(huì)走主鍵索引，不可能沒(méi)有走到索引。那會(huì)是什么原因呢？
上面我們提到，這個(gè)業(yè)務(wù)操作里是開(kāi)啟了事務(wù)的，還原一下大體的執(zhí)行情況。

start transaction;
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1;
INSERT INTO a (num) values (1);
commit;

查了一下當(dāng)時(shí)的日志，發(fā)現(xiàn)1秒內(nèi)有大約200條請(qǐng)求對(duì)一條記錄做更新庫(kù)存的操作。
線索漸漸清晰起來(lái)了，事故現(xiàn)場(chǎng)大致應(yīng)該是這樣的：

結(jié)論

由于開(kāi)啟了事務(wù)，在高并發(fā)地對(duì)一條記錄進(jìn)行更新的情況下，多個(gè)請(qǐng)求會(huì)進(jìn)入排隊(duì)系統(tǒng)。由于鎖的競(jìng)爭(zhēng)是不公平的，當(dāng)多個(gè)事務(wù)同時(shí)對(duì)一條記錄進(jìn)行更新時(shí)，極端情況下，就可能會(huì)出現(xiàn)一個(gè)更新操作進(jìn)去排隊(duì)系統(tǒng)以后，一直拿不到鎖，超過(guò)500ms被kill了。

細(xì)節(jié)分析

以上的業(yè)務(wù)操作，update會(huì)先申請(qǐng)行鎖，拿到行鎖以后進(jìn)行更新，更新完以后會(huì)執(zhí)行插入操作。那么在插入操作的時(shí)候是否需要申請(qǐng)鎖呢？
答案是肯定的，不過(guò)這里的插入操作使用的是自增鎖。那自增鎖是什么級(jí)別的鎖呢？
如果存在自增字段，MySQL會(huì)維護(hù)一個(gè)自增鎖，和自增鎖相關(guān)的一個(gè)參數(shù)為（5.1.22版本之后加入）
innodb_autoinc_lock_mode：可以設(shè)定3個(gè)值，0，1，2

0：traditonal （每次都會(huì)產(chǎn)生表鎖）
1：consecutive （會(huì)產(chǎn)生一個(gè)輕量鎖，simple insert會(huì)獲得批量的鎖，保證連續(xù)插入）
2：interleaved （不會(huì)鎖表，來(lái)一個(gè)處理一個(gè)，并發(fā)最高）

Myisam引擎均為traditional，InnoDB默認(rèn)為1，輕量鎖。所以在InnoDB的情況下，這里的insert操作的性能比update操作更高。

優(yōu)化

有了以上結(jié)論以后，那如何優(yōu)化呢？
最簡(jiǎn)單的方案就是減少持有鎖的時(shí)間，處理方式非常簡(jiǎn)單，將更新操作放到最后執(zhí)行，從而縮短更新鎖的持有時(shí)間，避免類(lèi)似的超時(shí)問(wèn)題。

start transaction;
INSERT INTO a (num) values (1);
UPDATE a SET stock = stock - 1 WHERE id = 100 and stock >= 1;
commit;

參考資料：
業(yè)務(wù)優(yōu)化案例一則
mysql并發(fā)insert死鎖問(wèn)題——gap、插入意向鎖沖突
InnoDB并發(fā)插入，居然使用意向鎖？
MySQL自增鎖