記一次生產環境死鎖問題分析

一、問題背景

最近在做的項目中生產環境頻繁出現數據庫死鎖的問題，解決一個，又來一個，最后數據庫不死鎖了，多了個請求文件服務器永久阻塞的問題，也是折騰了許久才解決掉。

二、定位死鎖SQL

由于線上的問題已經處理掉了，只能稍微模擬一下定位的步驟。

復現

首先，我們打開一個 SQL 窗口，關閉 MySQL 數據庫的自動提交，然后去修改一條數據。

set autocommit = 0; -- 關閉數據庫自動提交
update fs_pdf_transfer set progress = 99 where pdf_transfer_id = 2441  -- 執行完后事務并沒有結束，需手動 commit

然后打開一個新窗口，去修改同一條記錄

update fs_pdf_transfer set progress = 98 where pdf_transfer_id = 2441

你會發現這個語句運行一會后就出現Lock wait的報錯

定位

接下來我們就去定位一下相關 SQL，(數據庫版本是 8.0.2)

SELECT * FROM information_schema.INNODB_TRX;

INNODB_TRX 表提供了當前在 InnoDB 內部執行的所有事務信息，包含事務是否在等待鎖，事務何時開始以及事務正在執行的SQL語句(如果有的話，sql語句阻塞就可以顯示)。

可以看到后面的 update 語句處于 LOCK WAIT 狀態，在 trx_query 字段可以看到后面執行的 SQL。

然后吶，我們想找造成鎖等待的源頭 SQL，這里肯定就是 trx_state 是 RUNNING 狀態的記錄了，表示這個事務一直是 RUNNING 狀態，沒有提交，也沒有回滾。但是這條記錄的 trx_query 里面是空的，其實這里為空的意思就是事務未提交也未回滾。

此時可以將該條記錄的 trx_mysql_thread_id，就是 13896 放在以下 SQL 中，然后執行。

select * from performance_schema.events_statements_current where THREAD_ID in (select THREAD_ID from performance_schema.threads where PROCESSLIST_ID=13829)

看到 SQL_TEXT 字段，還不是我們要查的 SQL 信息。

通過 performance_schema.events_statements_history表，查看數據庫最近執行的一些 sql 語句，同樣是將 trx_mysql_thread_id放進去

SELECT EVENT_ID,CURRENT_SCHEMA, SQL_TEXT FROM performance_schema.events_statements_history WHERE THREAD_ID in (SELECT THREAD_ID FROM performance_schema.threads WHERE PROCESSLIST_ID=13829) order by event_id

可以看到之前執行的 update fs_pdf_transfer set progress = 99 where pdf_transfer_id = 2441

show engine innodb status

show engine innodb status 是 MySQL 提供的一個用于查看 innodb 引擎時間信息的工具，就目前來說有兩處比較常用的地方一、死鎖分析 二、innodb 內存使用情況。

執行這個之前，測試環境我們可以先設置下 set GLOBAL innodb_status_output_locks=ON;這樣輸出的信息更詳細。

---TRANSACTION 3861095, ACTIVE 1204 sec
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 13829, OS thread handle 140147875874560, query id 2483260 192.168.18.214 root
TABLE LOCK table `erow_biz`.`fs_pdf_transfer` trx id 3861095 lock mode IX
RECORD LOCKS space id 2351 page no 6 n bits 112 index PRIMARY of table `erow_biz`.`fs_pdf_transfer` trx id 3861095 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 33; compact format; info bits 128

可以看到第二個 update 語句鎖等待的詳細信息，這里顯示有兩個鎖，一個意向排他鎖IX（表級鎖），一個記錄上的行鎖（X）

三、線上問題

通過上面的步驟，我們大致能夠定位到出現問題的SQL。

先delete再insert

此次線上問題，我最終定位到的是一條刪除 SQL，然后找到對應的 Java 代碼，分析這塊代碼發現，是在同一個事務里先執行了刪除操作，然后再執行了插入操作，參數相同，類似這樣：

delete from fs_file where file_id = 111;
insert into fs_file(file_id) values(111);

網上一頓查，最后找到了這位大佬的文章分析：MySQL死鎖案例分:先delete，再insert，導致死鎖

最后的解決辦法就是在刪除前先查詢，如果有再刪除。

此時，此處的死鎖問題就解決掉了。

但是后面出現了新的死鎖。

先insert再update

新的死鎖問題定位到的代碼，是在同一個事務里先執行insert操作，接著執行 update操作。主鍵是自增的。

這個通過 show engine innodb status 看到如下信息：

*** (1) TRANSACTION:
TRANSACTION 4949999, ACTIVE 1 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 107 lock struct(s), heap size 24696, 5998 row lock(s), undo log entries 3
MySQL thread id 97584, OS thread handle 140126962161408, query id 12685049 192.168.1.224 root updating
update  
        ytb_package_file
     
        set pdf_transfer_id = 5673, transfer_status = 'TRANSFER_DOING'
        where source_file_guid = '83f87744-210c-4b87-be3a-ea7fc066dc4f'
        and template_detail_id = 0

*** (1) HOLDS THE LOCK(S): -- 持有鎖
RECORD LOCKS space id 3171 page no 5 n bits 144 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949999 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3171 page no 337 n bits 136 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949999 lock_mode X waiting  -- 等待鎖（136）


*** (2) TRANSACTION:
TRANSACTION 4949998, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 3
MySQL thread id 97582, OS thread handle 140126975891200, query id 12685057 192.168.1.224 root updating
update  
        ytb_package_file
     
        set pdf_transfer_id = 5674, transfer_status = 'TRANSFER_DOING'
        where source_file_guid = 'c4580bde-38c5-43dd-9342-4988c17541e2'
        and template_detail_id = 0

*** (2) HOLDS THE LOCK(S): -- -- 持有鎖
RECORD LOCKS space id 3171 page no 337 n bits 136 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949998 lock_mode X locks rec but not gap

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3171 page no 5 n bits 144 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949998 lock_mode X waiting  -- 等待鎖（144）


*** WE ROLL BACK TRANSACTION (2)

兩個事務同時持有對方需要的鎖，這個問題的具體原因還是因為我太菜了，沒分析出來，后面有了進展再補上吧。

代碼的話，將 insert 和 update 放不同的事務就解決掉這個死鎖問題了。

請求永久阻塞

在處理完上面的死鎖問題后，生產環境還是經常卡死，懷疑還有其他地方有死鎖問題，但是根本找不到，奇怪的是測試環境一切正常，就是生產環境經常卡死，最后通過日志分析，發現老是卡在使用 Feign 調用文件服務的一個地方，文件服務一切正常，業務服務發送請求上傳文件，請求都沒發出去就一直阻塞在這，百思不得其解。

后面通過 jstack 命令分析，發現如下信息。

"com.alibaba.nacos.client.Worker.longPolling.fixed-192.168.1.225_8848" #73 daemon prio=5 os_prio=0 tid=0x00007f4d48005000 nid=0xdad runnable [0x00007f4e2f8fb000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
	- locked <0x000000071eba9618> (a java.io.BufferedInputStream)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)

好像是和 HttpClient 有關系，一頓搜索終于發現端倪：竟然是 jdk 的一個 bug，詳情請看這篇分析： Java HttpClient execute 永久阻塞問題

恰巧生產環境的 JDK 版本不在這個 bug 的修復范圍內。

奇怪為啥測試環境沒有這個問題，然后我去看了下測試環境 OpenFeign 的配置：

feign:
  sentinel:
    enabled: true
  okhttp:
    enabled: true
  httpclient:
    enabled: false

好吧，破案了，測試環境服務間調用使用的是 okhttp，正式環境是 httpclient，遂改成 okhttp 問題解決！

MySql各種鎖機制的學習