線上BUG：MySQL死鎖分析實(shí)戰(zhàn)
本文轉(zhuǎn)載自微信公眾號「不送花的程序猿」，作者Howinfun 。轉(zhuǎn)載本文請聯(lián)系不送花的程序猿公眾號。
1 線上告警
我們不需要關(guān)注截圖中得其他信息，只要能看到打印得org.springframework.dao.DeadlockLoserDataAccessException就足夠了，就是MySQL發(fā)生死鎖導(dǎo)致服務(wù)拋異常。
關(guān)于接口的邏輯，可以大概描述為：C端調(diào)用接口查詢店鋪的追蹤事件列表，如果查詢?yōu)榭樟斜韯t順便給初始化，這里的初始化是批量插入一批事件追蹤列表，然后再返回，這里要給到一個(gè)關(guān)于表的信息點(diǎn)：這個(gè)表有主鍵索引和唯一索引。
1.1 云日志&死鎖日志
不管是云日志還是死鎖日志，都是顯示著是并發(fā)重復(fù)插入導(dǎo)致的死鎖，下面我就簡單放一下云日志的截圖，關(guān)于死鎖的日志就不放了，因?yàn)橄旅鎸⒆约号獋€(gè)demo來仿造并發(fā)重復(fù)請求導(dǎo)致批量插入發(fā)生死鎖。
2 相關(guān)鎖概念
2.1 INSERT語句如何加鎖
首先我們得先知道在執(zhí)行 INSERT 語句時(shí)，引擎(默認(rèn)InnoDb)是如何加鎖的。
默認(rèn)情況下，執(zhí)行 INSERT 語句是不用加鎖的，
不過如果事務(wù)中執(zhí)行一條 INSERT 語句，會(huì)先定位到該記錄在 B+ 樹的位置時(shí)，接著判斷該位置的下一條記錄被加了 grap 鎖;如果是的話會(huì)在記錄上加上一種類型為插入意向鎖的鎖，最后事務(wù)進(jìn)入等待狀態(tài)。
插入意向鎖是行級別的，也是一種間隙鎖。插入意向鎖之間互相兼容，多個(gè)事務(wù)可以同時(shí)對同一區(qū)間加上插入意向鎖;還有在事務(wù)中，如果成功插入記錄并且還未提交事務(wù)，那么當(dāng)前事務(wù)還會(huì)持有插入記錄的行鎖。
2.2 鍵發(fā)生重復(fù)沖突
如果當(dāng)插入記錄時(shí)遇到重復(fù)鍵，當(dāng)前事務(wù)會(huì)在生成錯(cuò)誤信息前，對記錄加上S鎖，如果是唯一索引發(fā)生的重復(fù)鍵，會(huì)加上S型的next-key鎖。
3 實(shí)踐出真知
下面我們開始上例子了。
3.1 表信息
使用現(xiàn)有的表：
- 用戶表
- 字段有：id、name、gender、user_type
- id為主鍵，name加了唯一索引;這里加唯一索引是要和上面的告警對齊。
- CREATE TABLE `user` (
- `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
- `name` varchar(20) NOT NULL,
- `gender` char(1) NOT NULL,
- `user_type` varchar(2) NOT NULL,
- PRIMARY KEY (`id`),
- UNIQUE KEY `uk_name` (`name`)
- ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
3.2 單元測試
接著是單元測試：
entity、mapper和service就直接省略過了。
單元測試主要是為了模擬線上的場景，前端并發(fā)發(fā)起請求，導(dǎo)致發(fā)生并發(fā)批量插入同一批數(shù)據(jù)。
3.2.1 代碼如下
模擬并發(fā)數(shù)3：
- @SpringBootTest(classes = MysqlInActionApplication.class)
- @RunWith(SpringRunner.class)
- public class MysqlInActionApplicationTests {
- @Autowired
- private UserService userService;
- /**
- * 線程數(shù)
- */
- private static final int threadNum = 3;
- /**
- * 控制同時(shí)請求
- */
- private static final CountDownLatch countDownLatch = new CountDownLatch(threadNum);
- /**
- * 用戶請求
- */
- class UserRequest implements Runnable{
- @Override
- public void run() {
- try {
- // 等待
- countDownLatch.await();
- } catch (InterruptedException e) {
- e.printStackTrace();
- }
- // 批量插入用戶，插入數(shù)據(jù)不變
- saveUserList();
- }
- }
- @Test
- public void contextLoads() {
- for (int i = 0; i < threadNum; i++) {
- new Thread(new UserRequest()).start();
- // 計(jì)數(shù)減一
- countDownLatch.countDown();
- }
- try {
- Thread.currentThread().join();
- } catch (InterruptedException e) {
- e.printStackTrace();
- }
- }
- /**
- * 批量插入用戶
- */
- public void saveUserList(){
- List<User> userList = new ArrayList<>();
- userList.add(new User().setName("winfun").setGender("m").setUserType("1"));
- userList.add(new User().setName("fenghao").setGender("w").setUserType("2"));
- userList.add(new User().setName("luff").setGender("m").setUserType("1"));
- this.userService.saveBatch(userList);
- }
- }
3.2.2 運(yùn)行結(jié)果
我們可以看到，基本和上面的告警信息是保持一致的了，直接拋出死鎖的異常。
3.3 MySQL 日志
我們再看看mysql的死鎖日志：
- show engine innodb status;
- ------------------------
- LATEST DETECTED DEADLOCK
- ------------------------
- 2021-07-03 12:36:02 0x7000082df000
- *** (1) TRANSACTION:
- TRANSACTION 25374, ACTIVE 0 sec inserting
- mysql tables in use 1, locked 1
- LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
- MySQL thread id 17, OS thread handle 123145438982144, query id 356 localhost 127.0.0.1 root update
- INSERT INTO user ( gender,
- name,
- user_type ) VALUES ( 'm',
- 'winfun',
- '1' )
- *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25374 lock mode S waiting
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
- *** (2) TRANSACTION:
- TRANSACTION 25373, ACTIVE 0 sec inserting
- mysql tables in use 1, locked 1
- 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
- MySQL thread id 19, OS thread handle 123145439539200, query id 369 localhost 127.0.0.1 root update
- INSERT INTO user ( gender,
- name,
- user_type ) VALUES ( 'w',
- 'fenghao',
- '2' )
- *** (2) HOLDS THE LOCK(S):
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25373 lock_mode X locks rec but not gap
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
- *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25373 lock_mode X locks gap before rec insert intention waiting
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
- *** WE ROLL BACK TRANSACTION (1)
3.3.1 事務(wù)一信息
- *** (1) TRANSACTION:
- TRANSACTION 25374, ACTIVE 0 sec inserting
- mysql tables in use 1, locked 1
- LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
- MySQL thread id 17, OS thread handle 123145438982144, query id 356 localhost 127.0.0.1 root update
- INSERT INTO user ( gender,
- name,
- user_type ) VALUES ( 'm',
- 'winfun',
- '1' )
事務(wù)一的trascationId為25374，存活0秒
事務(wù)一執(zhí)行的SQL為：INSERT INTO user ( gender,name,user_type ) VALUES ( 'm','winfun','1' )語句
- INSERT INTO user ( gender,name,user_type ) VALUES ( 'm','winfun','1' )
3.3.2 事務(wù)一正在等待的鎖
- *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25374 lock mode S waiting
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
事務(wù)一正在等待插入記錄的S型的next-key鎖。
3.3.3 事務(wù)二的信息
- *** (2) TRANSACTION:
- TRANSACTION 25373, ACTIVE 0 sec inserting
- mysql tables in use 1, locked 1
- 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
- MySQL thread id 19, OS thread handle 123145439539200, query id 369 localhost 127.0.0.1 root update
- INSERT INTO user ( gender,
- name,
- user_type ) VALUES ( 'w',
- 'fenghao',
事務(wù)二的事務(wù)ID為25373，存活0秒
事務(wù)一執(zhí)行的SQL為：INSERT INTO user ( gender,name,user_type ) VALUES ( 'w','fenghao','2' )語句
- INSERT INTO user ( gender,name,user_type ) VALUES ( 'w','fenghao','2' )
3.3.4 事務(wù)二持有鎖信息
- *** (2) HOLDS THE LOCK(S):
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25373 lock_mode X locks rec but not gap
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
事務(wù)二持有 name 為 winfun 這一行唯一二級索引的X鎖，但不是gap鎖。
3.3.5 事務(wù)二等待的鎖
- *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
- RECORD LOCKS space id 62 page no 4 n bits 72 index uk_name of table `test`.`user` trx id 25373 lock_mode X locks gap before rec insert intention waiting
- Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
- 0: len 6; hex 77696e66756e; asc winfun;;
- 1: len 8; hex 0000000000000001; asc ;;
事務(wù)二在添加插入意向鎖時(shí)發(fā)現(xiàn)記錄已經(jīng)被加上X型的間隙鎖，所以無法添加，只能等待鎖釋放。
3.3.6 最后的解決
- *** WE ROLL BACK TRANSACTION (1)
InnoDb 回滾了事務(wù)一，從而讓事務(wù)一接觸
3.4 分析總結(jié)：
- 事務(wù)一和事務(wù)二是并發(fā)批量插入同一批數(shù)據(jù)
- 事務(wù)二先執(zhí)行，成功插入 winfun這條記錄，然后對這條記錄加上了行鎖
- 接著事務(wù)一進(jìn)來了，發(fā)現(xiàn)winfun這個(gè)key是重復(fù)沖突了，接著在返回報(bào)錯(cuò)信息前，對winfun這條記錄加上S型的next-key鎖，但是發(fā)現(xiàn)winfun這條記錄上已經(jīng)有一個(gè)行鎖，所以只能等待
- 接著事務(wù)二進(jìn)行第二條記錄的插入，即插入fenghao;此時(shí)發(fā)現(xiàn)它的下一條記錄，即winfun記錄處已經(jīng)有事務(wù)一要加入next-key鎖，導(dǎo)致產(chǎn)生沖突，所以事務(wù)二也進(jìn)入等待
- 最后，只能回滾事務(wù)一，從而讓事務(wù)二完整執(zhí)行下去。
4 最后
最后如何解決線上這個(gè)問題呢?
其實(shí)很簡單，可以上分布式鎖，但是我們這場景沒有必要，反而會(huì)一定程度上增加接口的耗時(shí);并且我們這個(gè)是C端接口，完全沒有必要擁有初始化店鋪數(shù)據(jù)的能力，把這能力保留在Admin端的接口即可;所以最后將初始化，即批量插入初始化數(shù)據(jù)的邏輯干掉即可～
