線上BUG：MySQL死鎖分析實戰

不送花的程式猿發表於2021-07-04
MySql

原文連結：線上BUG：MySQL死鎖分析實戰

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' )語句

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' )語句

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型的間隙鎖，所以無法新增，只能等待鎖釋放。

最後的解決

*** WE ROLL BACK TRANSACTION (1)

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

分析總結：

  1. 事務一和事務二是併發批量插入同一批資料
  2. 事務二先執行，成功插入 winfun這條記錄，然後對這條記錄加上了行鎖
  3. 接著事務一進來了，發現winfun這個key是重複衝突了，接著在返回報錯資訊前，對winfun這條記錄加上S型的next-key鎖，但是發現winfun這條記錄上已經有一個行鎖，所以只能等待
  4. 接著事務二進行第二條記錄的插入，即插入fenghao;此時發現它的下一條記錄，即winfun記錄處已經有事務一要加入next-key鎖，導致產生衝突，所以事務二也進入等待
  5. 最後，只能回滾事務一，從而讓事務二完整執行下去。

最後

最後如何解決線上這個問題呢？

其實很簡單，可以上分散式鎖，但是我們這場景沒有必要，反而會一定程度上增加介面的耗時；並且我們這個是C端介面，完全沒有必要擁有初始化店鋪資料的能力，把這能力保留在Admin端的介面即可；所以最後將初始化，即批量插入初始化資料的邏輯幹掉即可～

相關文章