mysql len hex asc_线上频出MySQL死锁问题！分享一下自己教科书般的排查和分析过程！...
本文主要是講過程與思路，從手上的日志來反推故障現(xiàn)場，最后模擬出事故現(xiàn)場。沒有過度講解理論的一些知識(shí)，主要是偏分析。
文章參考的理論知識(shí)在最后，同時(shí)也將本次案例提交 ISSUE 給：https://github.com/aneasystone/mysql-deadlocks/issues/22?倉庫。
項(xiàng)目源碼地址：https://github.com/LiWenGu/transaction_lock.git
1. 日志
1.1 業(yè)務(wù)日志
一直平穩(wěn)運(yùn)行大半年的代碼，突然在最近幾天頻出現(xiàn)死鎖異常，業(yè)務(wù)機(jī)器大概每一兩天在業(yè)務(wù)高峰期發(fā)生一次如下的業(yè)務(wù)日志：INFO 57553 ---?[ConsumerThread2] org.example.controller.TestController ???:?全局鏈路跟蹤id:2的日志：[TransactionReqVO(userId=4, money=4), TransactionReqVO(userId=2, money=2), TransactionReqVO(userId=5, money=5)]
INFO 57553 ---?[ConsumerThread1] org.example.controller.TestController ???:?全局鏈路跟蹤id:1的日志：[TransactionReqVO(userId=5, money=5), TransactionReqVO(userId=1, money=1), TransactionReqVO(userId=4, money=4)]
ERROR 57553 ---?[ConsumerThread2] org.example.controller.TestController ???:?全局鏈路跟蹤id:2的異常：
###?Error?updating?database.??Cause:?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
###?The?error?may?exist?in?org/example/mapper/TestTableMapper.java?(best?guess)
###?The?error?may?involve?org.example.mapper.TestTableMapper.update-Inline
###?The?error?occurred?while?setting?parameters
###?SQL:?UPDATE?test_table?SET?money?=?money?+???WHERE?user_id?=??
###?Cause:?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
;?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction;?nested?exception?is?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
org.springframework.dao.DeadlockLoserDataAccessException:
###?Error?updating?database.??Cause:?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
###?The?error?may?exist?in?org/example/mapper/TestTableMapper.java?(best?guess)
###?The?error?may?involve?org.example.mapper.TestTableMapper.update-Inline
###?The?error?occurred?while?setting?parameters
###?SQL:?UPDATE?test_table?SET?money?=?money?+???WHERE?user_id?=??
###?Cause:?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
;?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction;?nested?exception?is?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException:?Deadlock?found?when?trying?to?get?lock;?try?restarting?transaction
at?org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:266)?~[spring-jdbc-5.0.13.RELEASE.jar:5.0.13.RELEASE]
at?org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)?~[spring-jdbc-5.0.13.RELEASE.jar:5.0.13.RELEASE]
at?org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)?~[mybatis-spring-2.0.1.jar:2.0.1]
at?org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)?~[mybatis-spring-2.0.1.jar:2.0.1]
at?com.sun.proxy.$Proxy59.update(Unknown?Source)?~[na:na]
at?org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294)?~[mybatis-spring-2.0.1.jar:2.0.1]
at?org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:67)?~[mybatis-3.5.1.jar:3.5.1]
at?org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:58)?~[mybatis-3.5.1.jar:3.5.1]
at?com.sun.proxy.$Proxy62.update(Unknown?Source)?~[na:na]
at?org.example.service.impl.TestServiceImpl.update(TestServiceImpl.java:16)?~[classes/:na]
at?org.example.manager.impl.BizManagerImpl.transactionMoney(BizManagerImpl.java:25)?~[classes/:na]
at?org.example.manager.impl.BizManagerImpl$$FastClassBySpringCGLIB$$824241b9.invoke()?~[classes/:na]
Deadlock?非常顯眼，說明業(yè)務(wù)上出現(xiàn)了死鎖，肯定是業(yè)務(wù)上有問題。但是該業(yè)務(wù)代碼一直運(yùn)行了大半年，查看 Git 記錄也發(fā)現(xiàn)最近沒人動(dòng)該業(yè)務(wù)相關(guān)代碼，說明該業(yè)務(wù)之前就可能有問題，只是最近才達(dá)到了觸發(fā)這種異常的條件。
對該日志做個(gè)簡單的總結(jié)：
1.這是什么錯(cuò)誤日志？8行：### SQL: UPDATE test_table SET money = money + ? WHERE user_id = ?
9行：### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
從第 8~9 行可以得知，該錯(cuò)誤是數(shù)據(jù)庫的錯(cuò)誤，是死鎖錯(cuò)誤異常而導(dǎo)致的回滾，關(guān)鍵 SQL 是：UPDATE test_table SET money = money + ? WHERE user_id = ?
2.核心錯(cuò)誤的調(diào)用方法是哪個(gè)，即事務(wù)開始的方法是哪個(gè)?
30行：at org.example.manager.impl.BizManagerImpl.transactionMoney(BizManagerImpl.java:25) ~[classes/:na] 31行：at org.example.manager.impl.BizManagerImpl$$FastClassBySpringCGLIB$$824241b9.invoke() ~[classes/:na]
過濾了 jdk 類、spring 類、mybatis 類后，得到核心的業(yè)務(wù)錯(cuò)誤代碼(30~31 行)，31 行為 Spring 的代理執(zhí)行，30 行才是真正最開始執(zhí)行業(yè)務(wù)代碼：BizManagerImpl.transactionMoney
1.2 數(shù)據(jù)庫死鎖日志
接著去查看該庫對應(yīng)的數(shù)據(jù)庫死鎖日志，使用命令：show innodb engine status，過濾掉非重要的日志后如下：------------------------
LATEST?DETECTED?DEADLOCK
------------------------
2020-07-14?23:34:29?0x7f958f1d5700
***?(1)?TRANSACTION:
TRANSACTION?95146580,?ACTIVE?2?sec?starting?index?read
mysql?tables?in?use?1,?locked?1
LOCK?WAIT?4?lock?struct(s),?heap?size?1136,?5?row?lock(s),?undo?log?entries?2
MySQL?thread?id?6264489,?OS?thread?handle?140273305761536,?query?id?837446998?10.10.59.164?root?updating
UPDATE?test_table?SET?money?=?money?+?5?WHERE?user_id?=?5
***?(1)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:
RECORD?LOCKS?space?id?71816?page?no?4?n?bits?80?index?idx_user_id?of?table?`mall`.`test_table`?trx?id?95146580?lock_mode?X?locks?rec?but?not?gap?waiting
Record?lock,?heap?no?3?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
0:?len?8;?hex?8000000000000005;?asc?????????;;
1:?len?8;?hex?8000000000000006;?asc?????????;;
***?(2)?TRANSACTION:
TRANSACTION?95146581,?ACTIVE?2?sec?starting?index?read
mysql?tables?in?use?1,?locked?1
4?lock?struct(s),?heap?size?1136,?5?row?lock(s),?undo?log?entries?2
MySQL?thread?id?6264490,?OS?thread?handle?140280327919360,?query?id?837446999?10.10.59.164?root?updating
UPDATE?test_table?SET?money?=?money?+?4?WHERE?user_id?=?4
***?(2)?HOLDS?THE?LOCK(S):
RECORD?LOCKS?space?id?71816?page?no?4?n?bits?80?index?idx_user_id?of?table?`mall`.`test_table`?trx?id?95146581?lock_mode?X?locks?rec?but?not?gap
Record?lock,?heap?no?3?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
0:?len?8;?hex?8000000000000005;?asc?????????;;
1:?len?8;?hex?8000000000000006;?asc?????????;;
Record?lock,?heap?no?5?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
0:?len?8;?hex?8000000000000001;?asc?????????;;
1:?len?8;?hex?8000000000000002;?asc?????????;;
***?(2)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:
RECORD?LOCKS?space?id?71816?page?no?4?n?bits?80?index?idx_user_id?of?table?`mall`.`test_table`?trx?id?95146581?lock_mode?X?locks?rec?but?not?gap?waiting
Record?lock,?heap?no?2?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
0:?len?8;?hex?8000000000000004;?asc?????????;;
1:?len?8;?hex?8000000000000005;?asc?????????;;
***?WE?ROLL?BACK?TRANSACTION?(2)
關(guān)鍵點(diǎn)總結(jié)如下：
1.該庫中最近一次死鎖發(fā)生的時(shí)間是什么時(shí)候？4行：2020-07-14 23:34:29 0x7f958f1d5700
得知，最近一次死鎖發(fā)生在 2020-07-14 23:34:29
2.該次死鎖導(dǎo)致的兩個(gè)事務(wù)的重要信息？12行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table?mall.test_table?trx id 95146580 lock_mode X locks rec but not gap waiting
得知，事務(wù) 1 等待的鎖為：lock_mode X locks rec but not gap waiting24行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table?mall.test_table?trx id 95146581 lock_mode X locks rec but not gap
得知，事務(wù) 2 持有的鎖為：lock_mode X locks rec but not gap34行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table?mall.test_table?trx id 95146581 lock_mode X locks rec but not gap waiting
得知，事務(wù) 2 等待的鎖為：lock_mode X locks rec but not gap waiting39行：*** WE ROLL BACK TRANSACTION (2)
得知，最后回滾的是事務(wù) 1從 12、24、34 行：index idx_user_id of table?mall.test_table
得知：導(dǎo)致該次死鎖的索引為：idx_user_id
3.能知道導(dǎo)致死鎖的兩個(gè)具體 SQL 嗎？不能，產(chǎn)生死鎖的情況各式各樣，事務(wù)中的 SQL 可能不止有兩個(gè) SQL，單從死鎖日志是沒法知道具體原因的，必須要結(jié)合業(yè)務(wù)代碼查看事務(wù)上下文查看
2. 理論知識(shí)
排查過程中發(fā)現(xiàn)有個(gè)特點(diǎn)，影響的都是是線上的大用戶。由于當(dāng)時(shí)我很久沒看死鎖相關(guān)的理論知識(shí)，因此先去了解下相關(guān)死鎖的基本知識(shí)。
2.1 死鎖的條件互斥條件：一個(gè)資源每次只能被一個(gè)進(jìn)程使用。
占有且等待：一個(gè)進(jìn)程因請求資源而阻塞時(shí)，對已獲得的資源保持不放。
不可強(qiáng)行占有：進(jìn)程已獲得的資源，在末使用完之前，不能強(qiáng)行剝奪。
循環(huán)等待條件：若干進(jìn)程之間形成一種頭尾相接的循環(huán)等待資源關(guān)系。
破壞死鎖也很簡單，四個(gè)條件破一個(gè)即可。(本案例是破壞的 4)
2.2 數(shù)據(jù)庫的鎖類型
數(shù)據(jù)庫的死鎖比較復(fù)雜，主要是由 Insert、Update(其實(shí)在開發(fā)中 Delete 或 For Update 是不怎么不考慮的，因?yàn)樵趯?shí)際業(yè)務(wù)代碼中我們一般不會(huì)有 Delete 或 For Update 的操作，刪除都是物理刪除，for update 建議少用，除非你知道非用不可)。
InnoDB 的鎖：共享鎖與獨(dú)占鎖(S、X)
意向鎖
記錄鎖(Record Locks)
間隙鎖(Gap Locks)
Next-Key Locks
插入意向鎖
自增鎖
空間索引斷言鎖
這里參考了官網(wǎng)的 Innodb 鎖分類，從死鎖日志的?lock_mode X locks rec but not gap?，大致能知道，這里可能涉及了 X 鎖、記錄鎖、間隙鎖(但是有個(gè) not，說明不涉及)。
3. ?從死鎖日志分析
分析之前先得到該表的建表語句：show create table test_table;：CREATE?TABLE?`test_table`?(
`id`?bigint(20)?NOT?NULL?AUTO_INCREMENT,
`money`?bigint(20)?NOT?NULL,
`user_id`?bigint(20)?NOT?NULL,
PRIMARY?KEY?(`id`),
KEY?`idx_user_id`?(`user_id`)
)?ENGINE=InnoDB?AUTO_INCREMENT=5?DEFAULT?CHARSET=utf8
接著結(jié)合死鎖日志、鎖的種類、建表語句得出以下模糊的結(jié)論：
1.從死鎖日志的 10、12 行結(jié)合建表索引得知10行：UPDATE test_table SET money = money + 5 WHERE user_id = 5
12行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table?mall.test_table?trx id 95146580
事務(wù)1的?UPDATE test_table SET money = money + 5 WHERE user_id = 5? 語句在等待鎖：它通過普通索引 idx_user_id 更新，先獲取了 user_id=5 的 X 鎖，接著去申請對應(yīng)行的主鍵(Record Lock)的行鎖但是被阻塞(waiting)，并不包括間隙鎖(not gap)。具體是哪個(gè)主鍵我們并不清楚。
2.從死鎖日志的 22、24 行結(jié)合建表索引得知22行：UPDATE test_table SET money = money + 4 WHERE user_id = 4
24行：Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
事務(wù)2的?UPDATE test_table SET money = money + 4 WHERE user_id = 4? 語句在持有鎖：它通過普通索引 idx_user_id 更新，先獲取了 user_id=4 的 X 鎖，接著去申請對應(yīng)行的主鍵(Record Lock)的行鎖成功了，并不包括間隙鎖(not gap)。具體是成功的哪個(gè)主鍵我們并不清楚。
3.從死鎖日志的 22、34 行結(jié)合建表索引得知22行：UPDATE test_table SET money = money + 4 WHERE user_id = 4
34行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table?mall.test_table?trx id 95146581 lock_mode X locks rec but not gap waiting
事務(wù)2的?UPDATE test_table SET money = money + 4 WHERE user_id = 4? 語句在等待鎖：它通過普通索引 idx_user_id 更新，先獲取了 user_id=4 的 X 鎖，接著去申請對應(yīng)行的主鍵(Record Lock)的行鎖但是被阻塞(waiting)，并不包括間隙鎖(not gap)。具體是哪個(gè)主鍵我們并不清楚。
模糊結(jié)論肯定是有問題的，最大的問題在于導(dǎo)致的 SQL 語句不正確，即：死鎖的原因是真實(shí)的，但是具體是因?yàn)槟男?SQL 導(dǎo)致的死鎖是不清楚的。接著我們整理得到了以下可能有問題的表格：
事務(wù)1事務(wù)2某些 SQL某些 SQL
某個(gè) SQL 的 user_id = 5 行更新操作被阻塞了某個(gè) SQL 的 user_id = 4 獲得了鎖但是又阻塞了
某些 SQL某些 SQL
可以得知，其實(shí)單從死鎖日志分析是比較片面的，因?yàn)?user_id 為 4、5 這兩個(gè) update 操作是不會(huì)有互相阻塞的問題，肯定是有別的 SQL 影響，我們需要額外從業(yè)務(wù)日志分析才能還原完整的現(xiàn)場。
4. 從業(yè)務(wù)日志分析
從死鎖日志是不能完全知道導(dǎo)致的關(guān)鍵 SQL 和故障現(xiàn)場的整體流程，因此我們要借助業(yè)務(wù)日志來完成最后對故障現(xiàn)場的分析：
通過前面對業(yè)務(wù)日志的分析，我們知道最關(guān)鍵的調(diào)用方法是?BizManagerImpl.transactionMoney，查看對應(yīng)源碼：@Override
@Transactional
public?boolean?transactionMoney(List?transactionReqVOList)?throws?Exception{
for?(TransactionReqVO?transactionReqVO?:?transactionReqVOList)?{
//?模擬業(yè)務(wù)操作
Thread.sleep(1000);
int?updateCount?=?testTableService.update(transactionReqVO.getUserId(),?transactionReqVO.getMoney());
if?(updateCount?==?0)?{
log.error("轉(zhuǎn)賬異常："?+?transactionReqVO);
}
}
return?true;
}
可以知道，應(yīng)該是 for 循環(huán)事務(wù)的問題，但是具體是哪些 user_id 是不清楚的，接著我們查看業(yè)務(wù)日志的上下文，通過全鏈路 traceId(模擬) 做搜索，得到以下的日志：[ConsumerThread2] org.example.controller.TestController ? ?: 全局鏈路跟蹤id:2的日志：[TransactionReqVO(userId=4, money=4), TransactionReqVO(userId=2, money=2), TransactionReqVO(userId=5, money=5)]
[ConsumerThread1] org.example.controller.TestController ? ?: 全局鏈路跟蹤id:1的日志：[TransactionReqVO(userId=5, money=5), TransactionReqVO(userId=1, money=1), TransactionReqVO(userId=4, money=4)]
分析到這一步，我們已經(jīng)可以還原死鎖場景了，事務(wù)流程圖如下：
事務(wù)1事務(wù)2UPDATE test_table SET money = money + 4 WHERE user_id = 4UPDATE test_table SET money = money + 5 WHERE user_id = 5
UPDATE test_table SET money = money + 2 WHERE user_id = 2UPDATE test_table SET money = money + 1 WHERE user_id = 1
UPDATE test_table SET money = money + 5 WHERE user_id = 5UPDATE test_table SET money = money + 4 WHERE user_id = 4
5. 業(yè)務(wù)日志、死鎖日志結(jié)合分析
將死鎖日志分析得出的不正確表格加上業(yè)務(wù)日志分析得出正確表格，我們得出最終帶有理解的最終正確的事務(wù)表格：
事務(wù)1事務(wù)2UPDATE test_table SET money = money + 4 WHERE user_id = 4 持有 user_id 為 4 的行鎖UPDATE test_table SET money = money + 5 WHERE user_id = 5 持有 user_id 為 5 的行鎖
UPDATE test_table SET money = money + 2 WHERE user_id = 2?持有 user_id 為 2 的行鎖UPDATE test_table SET money = money + 1 WHERE user_id = 1?持有 user_id 為 1 的行鎖
UPDATE test_table SET money = money + 5 WHERE user_id = 5
阻塞中...等待持有 user_id 為 5 的行鎖解鎖UPDATE test_table SET money = money + 4 WHERE user_id = 4
阻塞中...user_id等待持有 user_id 為 4 的行鎖解鎖
回滾
提交
可以知道，其實(shí)死鎖日志的 SQL 是模糊的，但是原因是正確的，至于具體是哪些 SQL 導(dǎo)致的死鎖，是需要從業(yè)務(wù)日志來判定。
6. 善后
模擬出了事務(wù)2的場景，我們就可以對回滾的 SQL 執(zhí)行，來人工修復(fù)受到影響的用戶數(shù)據(jù)(客戶第一)。
也可以知道其實(shí)?transactionMoney()??方法不應(yīng)該加事務(wù)，因?yàn)樵摌I(yè)務(wù)場景每個(gè)用戶的更新是獨(dú)立的不應(yīng)該互相受到影響，但是當(dāng)某條更新失敗時(shí)，我們也要打印對應(yīng)的日志。
這里我們就知道為什么之前大半年都沒問題，最近才頻發(fā)這種異常，因?yàn)橹挥挟?dāng)兩個(gè)事務(wù)同時(shí)執(zhí)行，并且兩個(gè)事務(wù)中包含了相同的兩個(gè)或兩個(gè)以上的 user_id 才會(huì)可能觸發(fā)該異常。而這種 user_id 都是所謂的大用戶，像該示例中的 user_id 為 1、2 是小用戶，雖然它們也受到了影響，但是頻率是沒有 user_id 為 4、5 這種大用戶高的。
在實(shí)際的業(yè)務(wù)場景也證實(shí)了這點(diǎn)，不僅是發(fā)生故障的時(shí)間是集中在高峰期，而且發(fā)生故障的用戶也經(jīng)常有那幾個(gè)熟面孔，經(jīng)過后面復(fù)盤，這幾個(gè)熟面孔用戶也就是我們所說的”大用戶“(業(yè)務(wù)操作頻率高的用戶)。
7. 模擬項(xiàng)目源碼
為了模擬真實(shí)場景中的方法調(diào)用(消息接收調(diào)用執(zhí)行)，使用了線程來模擬。
并且使用線程睡眠來保證每個(gè)事務(wù)執(zhí)行夠長，來讓每次模擬執(zhí)行都必現(xiàn)異常。
項(xiàng)目結(jié)構(gòu)比較簡單， Controller -> Manager -> Service -> Mapper -> DB，執(zhí)行?curl 'localhost:8080/test/consumer'?后，查看命令行輸出即可看到業(yè)務(wù)異常日志。
對應(yīng)的死鎖日志需要到對應(yīng)的數(shù)據(jù)庫執(zhí)行：show engine innodb status?后可看到。
8. 最后
中間查閱了很多資料，發(fā)現(xiàn)有個(gè)項(xiàng)目總結(jié)了所有的死鎖日志對應(yīng)的可能 SQL：https://github.com/aneasystone/mysql-deadlocks，里面也講解了加鎖的各個(gè)細(xì)節(jié)過程，是非常值得一看的。
以下為該項(xiàng)目的部分截圖：
當(dāng)遇到復(fù)雜的業(yè)務(wù)場景，尤其是不熟悉的時(shí)候，這個(gè)是一個(gè)很好的參考資料。業(yè)務(wù)日志記錄、全鏈路跟蹤是非常非常重要的
總結(jié)
以上是生活随笔為你收集整理的mysql len hex asc_线上频出MySQL死锁问题！分享一下自己教科书般的排查和分析过程！...的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： mysql 5.7源码包安装教程_MYS
- 下一篇： 中科院sci分区表_最新 | 2020中