線上BUG：MySQL死鎖分析實戰

作者： Howinfun 2021-07-04 22:29:12

數據庫 MySQL

我們不需要關注截圖中得其他信息，只要能看到打印得org.springframework.dao.DeadlockLoserDataAccessException就足夠了，就是MySQL發生死鎖導致服務拋異常。

[[409159]]

本文轉載自微信公眾號「不送花的程序猿」，作者Howinfun 。轉載本文請聯系不送花的程序猿公眾號。

1 線上告警

我們不需要關注截圖中得其他信息，只要能看到打印得org.springframework.dao.DeadlockLoserDataAccessException就足夠了，就是MySQL發生死鎖導致服務拋異常。

關于接口的邏輯，可以大概描述為：C端調用接口查詢店鋪的追蹤事件列表，如果查詢為空列表則順便給初始化，這里的初始化是批量插入一批事件追蹤列表，然后再返回，這里要給到一個關于表的信息點：這個表有主鍵索引和唯一索引。

1.1 云日志&死鎖日志

不管是云日志還是死鎖日志，都是顯示著是并發重復插入導致的死鎖，下面我就簡單放一下云日志的截圖，關于死鎖的日志就不放了，因為下面將自己弄個demo來仿造并發重復請求導致批量插入發生死鎖。

2 相關鎖概念

2.1 INSERT語句如何加鎖

首先我們得先知道在執行 INSERT 語句時，引擎(默認InnoDb)是如何加鎖的。

默認情況下，執行 INSERT 語句是不用加鎖的，

不過如果事務中執行一條 INSERT 語句，會先定位到該記錄在 B+ 樹的位置時，接著判斷該位置的下一條記錄被加了 grap 鎖;如果是的話會在記錄上加上一種類型為插入意向鎖的鎖，最后事務進入等待狀態。

插入意向鎖是行級別的，也是一種間隙鎖。插入意向鎖之間互相兼容，多個事務可以同時對同一區間加上插入意向鎖;還有在事務中，如果成功插入記錄并且還未提交事務，那么當前事務還會持有插入記錄的行鎖。

2.2 鍵發生重復沖突

如果當插入記錄時遇到重復鍵，當前事務會在生成錯誤信息前，對記錄加上S鎖，如果是唯一索引發生的重復鍵，會加上S型的next-key鎖。

3 實踐出真知

下面我們開始上例子了。

3.1 表信息

使用現有的表：

用戶表
字段有：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就直接省略過了。

單元測試主要是為了模擬線上的場景，前端并發發起請求，導致發生并發批量插入同一批數據。

3.2.1 代碼如下

模擬并發數3：

@SpringBootTest(classes = MysqlInActionApplication.class) 
@RunWith(SpringRunner.class) 
public class MysqlInActionApplicationTests { 
 
  @Autowired 
  private UserService userService; 
   
  /** 
   * 線程數 
   */ 
  private static final int threadNum = 3; 
  /** 
   * 控制同時請求 
   */ 
  private static final CountDownLatch countDownLatch = new CountDownLatch(threadNum); 
 
  /** 
   * 用戶請求 
   */ 
  class UserRequest implements Runnable{ 
 
    @Override 
    public void run() { 
      try { 
        // 等待 
        countDownLatch.await(); 
      } catch (InterruptedException e) { 
        e.printStackTrace(); 
      } 
      // 批量插入用戶，插入數據不變 
      saveUserList(); 
    } 
  } 
 
  @Test 
  public void contextLoads() { 
    for (int i = 0; i < threadNum; i++) { 
      new Thread(new UserRequest()).start(); 
      // 計數減一 
      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 運行結果

我們可以看到，基本和上面的告警信息是保持一致的了，直接拋出死鎖的異常。

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 事務一信息

*** (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' )

事務一的trascationId為25374，存活0秒

事務一執行的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 事務一正在等待的鎖

*** (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         ;;

事務一正在等待插入記錄的S型的next-key鎖。

3.3.3 事務二的信息

*** (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',

事務二的事務ID為25373，存活0秒

事務一執行的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 事務二持有鎖信息

*** (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         ;;

事務二持有 name 為 winfun 這一行唯一二級索引的X鎖，但不是gap鎖。

3.3.5 事務二等待的鎖

*** (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         ;;

事務二在添加插入意向鎖時發現記錄已經被加上X型的間隙鎖，所以無法添加，只能等待鎖釋放。

3.3.6 最后的解決

*** WE ROLL BACK TRANSACTION (1)

InnoDb 回滾了事務一，從而讓事務一接觸

3.4 分析總結：

事務一和事務二是并發批量插入同一批數據
事務二先執行，成功插入 winfun這條記錄，然后對這條記錄加上了行鎖
接著事務一進來了，發現winfun這個key是重復沖突了，接著在返回報錯信息前，對winfun這條記錄加上S型的next-key鎖，但是發現winfun這條記錄上已經有一個行鎖，所以只能等待
接著事務二進行第二條記錄的插入，即插入fenghao;此時發現它的下一條記錄，即winfun記錄處已經有事務一要加入next-key鎖，導致產生沖突，所以事務二也進入等待
最后，只能回滾事務一，從而讓事務二完整執行下去。

4 最后

最后如何解決線上這個問題呢?

其實很簡單，可以上分布式鎖，但是我們這場景沒有必要，反而會一定程度上增加接口的耗時;并且我們這個是C端接口，完全沒有必要擁有初始化店鋪數據的能力，把這能力保留在Admin端的接口即可;所以最后將初始化，即批量插入初始化數據的邏輯干掉即可～

責任編輯：武曉燕來源：不送花的程序猿

MySQL 死鎖云日志