mark下自己近期在電商開發中遇到的一個問題－數據庫死鎖及其排查過程。
先拋一個業務報錯日志做為這次梳理的開始
上圖是我接收到的錯誤報警，SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction，錯誤信息顯示我們業務中有一條數據庫操作遇到了死鎖情況。接下來就開始我們的追查之旅。
1.執行“show engine innodb status”獲取INNODB引擎當前信息（show engine innodb status 詳細介紹）
------------------------ LATEST DETECTED DEADLOCK ------------------------ 2017-01-04 09:25:17 7f553477d700 *** (1) TRANSACTION: TRANSACTION 124378994, ACTIVE 0.007 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1184, 8 row lock(s), undo log entries 7 LOCK BLOCKING MySQL thread id: 11573556 block 11572504 MySQL thread id 11572504, OS thread handle 0x7f56342fb700, query id 3368968901 10.44.182.0 shzfstore updating UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15608' AND `quantity` >= '1' limit 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378994 lock_mode X locks rec but not gap waiting Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0 ...... *** (2) TRANSACTION: TRANSACTION 124378995, ACTIVE 0.004 sec starting index read mysql tables in use 1, locked 1 3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1 MySQL thread id 11573556, OS thread handle 0x7f553477d700, query id 3368968902 10.172.221.117 shzfstore updating UPDATE `sku` SET `quantity`=quantity-'1',`lock_stock`=lock_stock+'1',`sys_version`=sys_version+1 WHERE `id` = '15504' AND `quantity` >= '1' limit 1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 393 page no 45 n bits 248 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap Record lock, heap no 19 PHYSICAL RECORD: n_fields 19; compact format; info bits 0 ...... *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 393 page no 43 n bits 240 index `PRIMARY` of table `store_product`.`sku` trx id 124378995 lock_mode X locks rec but not gap waiting Record lock, heap no 81 PHYSICAL RECORD: n_fields 19; compact format; info bits 0 ...... *** WE ROLL BACK TRANSACTION (2) LATEST DETECTED DEADLOCK記錄了最近一次的死鎖情況。
2017-01-04 09:25:17時間跟我們接收到的報錯日志時間吻合。
上面還可以看出兩個事務之間發生鎖競爭時，給我們留下的部分數據
事務1
UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15608' ANDquantity>= '1' limit 1
事務2
UPDATEskuSETquantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHEREid= '15504' ANDquantity>= '1' limit 1
死鎖的兩個資源均被lock_mode X locks了
最后，mysql給了很重要的一個數據“WE ROLL BACK TRANSACTION (2)” MYSQL回滾了事務2。既然mysql回滾了事務2，那么肯定是事務2的語句觸發了死鎖，被mysql回滾了，也就是應該為報錯日志所記錄的那部分。同時，MYSQL執行了事務1，那么事務1的SQL語句肯定被記錄在BINLOG中了。
2.查看binlog日志，找出事務1所執行的語句
查找依據：
- SQL語句,根據LATEST DETECTED DEADLOCK提供的死鎖時記錄的sql語句。
- 線程ID(mysql的唯一標識): MySQL thread id 11572504
- 執行時間(時間線):2017-01-04 09:25:17 7f553477d700
根據以上三個標識，以及BINLOG的起始標志“BEGIN、COMMIT”，幾乎可以100%確定事務1所包含的SQL語句。
mysql查看binlog
mysql> show binary logs; #獲取binlog文件列表
mysql> show master status； #查看當前正在寫入的binlog文件
bt寶塔 使用mysqlbinlog提取binlog
/www/server/mysql/bin/mysqlbinlog --start-datetime="2019-09-10 11:40:00" /www/server/data/mysql-bin.000007 -r /www/test.sql
binlog信息大致如下
#170104 9:25:17 server id 3194178605 end_log_pos 137170469 CRC32 0x1b6559de Query thread_id=11572504 exec_time=0 error_code=0 SET TIMESTAMP=1483493117/*!*/; BEGIN ...... ### UPDATE `store_product`.`sku` ### WHERE ### @1=15504 ### @2=11516 ### @3=0.01 ### @4=120065 ### @5=109433 ### @6=19 ### SET ### @1=15504 ### @2=11516 ### @3=0.01 ### @4=120065 ### @5=109432 ### @6=20 # at 137172557 ...... ### UPDATE `store_product`.`sku` ### WHERE ### @1=15608 ### @2=11551 ### @3=0.01 ### @4=120077 ### @5=109426 ### @6=19 ### SET ### @1=15608 ### @2=11551 ### @3=0.01 ### @4=120077 ### @5=109425 ### @6=20 ...... COMMIT/*!*/; 3.還原事務2所包含的執行語句
事務1的語句找齊了，接下來找事務2的語句，還記得我們開頭提供的報錯日志嗎，那個日志里也詳細記錄了發起請求時的參數情況（截圖未展示），根據參數和我們處理業務的代碼，可以復現事務2所要執行的語句
BEGIN
...... ### UPDATE `store_product`.`sku` ### WHERE ### @1=15608 ### @2=11516 ### @3=0.01 ### @4=120065 ### @5=109433 ### @6=19 ### SET ### @1=15608 ### @2=11516 ### @3=0.01 ### @4=120065 ### @5=109432 ### @6=20 ...... ### UPDATE `store_product`.`sku` ### WHERE ### @1=15504 ### @2=11551 ### @3=0.01 ### @4=120077 ### @5=109426 ### @6=19 ### SET ### @1=15504 ### @2=11551 ### @3=0.01 ### @4=120077 ### @5=109425 ### @6=20 ...... COMMIT/*!*/; 根據兩個事務所執行的sql語句，目前可以還原死鎖產生的原因了
4.查看兩個事務執行語句的順序：
| 順序 | 事務1 | 事務2 | 說明 |
|---|---|---|---|
| 1 | begin | ||
| 2 | begin | ||
| 3 | UPDATE sku SET quantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHERE id = '15504' AND quantity >= '1' limit 1 |
事務1 給 sku表 id 15504記錄上 X 鎖 | |
| 4 | UPDATE sku SET quantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHERE id = '15608' AND quantity >= '1' limit 1 |
事務2 給 sku表 id 15608記錄上 X 鎖 | |
| 5 | UPDATE sku SET quantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHERE id = '15608' ANDquantity >= '1' limit 1 |
這里是關鍵，事務1想給sku表 id 15608上X鎖，發現被別人（事務2）上鎖了，等待鎖釋放 | |
| 6 | UPDATE sku SET quantity=quantity-'1',lock_stock=lock_stock+'1',sys_version=sys_version+1 WHERE id = '15504' AND quantity >= '1' limit 1 |
事物2打算給sku表id為15504記錄上 X 排它鎖，發現被其他事務上了，而且此事務居然還在等他提交，這時MYSQL立刻回滾事務2…(php發現MYSQL返回死鎖信息，記錄該信息到錯誤日志…發送回滾指令…mysql已經“幫”他回滾了…) | |
| 7 | 執行成功 | 事務1發現別人的鎖釋放了，獲得X鎖，執行成功 | |
| 8 | commit | 事務1執行成功，記錄binlog日志 |
解決方案
- 減小事務中的語句數量
- 在業務中調整語句的執行順序，例如可以按照where條件中字段的大小進行一下排序，按照排序后順序執行，讓死鎖變為鎖等待。
相關補充
- innodb的行鎖，鎖的是查詢條件中的索引字段，以及索引字段對應的primary key字段