閱讀本文大概需要 2.8 分鐘。

MySQL 對我說 「Too young, too naive!"

大概過程

在測試環境 Docker 容器中，在跨進程調用服務的時候，A 應用通過 Dubbo 調用 B 應用的 RPC 介面，發現 B 應用介面超時錯誤，接著通過 debug 和日誌，發現具體耗時的地方在於一句簡單 SQL 執行，但是耗時超過 1000ms。

通過查看資料庫的進程列表，發現是有死鎖鎖表了，很多進程狀態 status 處於 sending data，最後為鎖住的表添加索引，並且 kill 掉阻塞的請求，解除死鎖，服務速度恢復正常。

下面記錄的是大致排查過程：

通過觀察業務代碼，確認沒有內存溢出或者其它事務問題，於是只能考慮 Docker 環境的資料庫和 jvm 底層詳情了。

使用 Druid 監控 SQL 執行狀態

通過日誌，發現有一句 SQL 嚴重超時，一句簡單 SQL，原本是批量插入多條記錄，為了定位問題，測試時 Mybatis 只插入一條記錄，但即便如此，還是耗時 10 秒。

於是打算使用阿里巴巴的資料庫連接池 Druid 進行監控，監控 SQL 效果如下：

在 SQL 監控 Tab 中，可以看到執行 SQL 的具體情況，包括某條 SQL 語句執行的時間（平均、最慢）、SQL 執行次數、SQL 執行出錯的次數等。

上面顯示的是正常情況下，時間單位是 ms，正常的 SQL 一般在 10ms 之內，數據量大的控制在 30ms 之內，這樣用戶的使用體驗感才會良好。

所以說之前的 1000ms，是不可接受的結果。

通過 JMC 遠程監控 Tomcat

JMC(java mission control) 是 jdk 自帶的一個監控工具，在 jdk 的 bin 目錄下（java 大法好，該目錄下有很多實用的工具）。

此處加了一個 tomcat 無驗證模式：

#在tomcat的conf目錄下的catalina.sh增加如下java啟動參數：-Dcom.sun.management.jmxremote=true-Dcom.sun.management.jmxremote.port=8888-Dcom.sun.management.jmxremote.ssl=false-Dcom.sun.management.jmxremote.authenticate=false-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

下面是自己本地調試的截圖

然後打開 jmc，創建一個 JMX 連接，輸入對應的 ip 和 JMX 埠。接著可以設定一段時間內的飛行監控，監測這一分鐘內 jvm 具體參數

當時調試的時候，發現內存使用、CPU 佔用率、線程狀態也挺正常的，沒有發現明顯的異常錯誤，效果如下圖：

唯一比較耗時的是在代碼 tab 頁中，當時發現了大量的 I/O，比上圖的比例還高，當時大概佔了 80%，查看調用樹，很多循環 tcp socket 連接。

考慮到應用中本來就有很多需要 io 以及 netty 也需要 tcp 連接，所以大概排除了 jvm 虛擬機的問題，然後就去排查 MySQL 的問題。

排查 MySQL

在了解 MySQL 鎖概念的時候，由於現在使用的比較多的是 InnoDB，所以可以著重看看 InnoDB 鎖問題。

直接執行 SQL 語句

通過 DEBUG 代碼，從 mybatis 中取出映射後的SQL語句，在 MySQL 客戶端直接執行 SQL 和 Explain 查看執行計劃，速度都很快，排除了 SQL 語句的問題。

查看 MySQL 線程列表

show processlist;

從圖中可以看出，有些線程的狀態處於 sending data，查閱資料：所謂的「Sending data」並不是單純的發送數據，而是包括「收集 + 發送 數據」。

然後後面一列 info 顯示的是具體信息，是查詢用來生成主鍵 ID 的函數，之前速度都很快，為啥突然就這麼慢呢，於是回過頭去查看該函數：

select next_value into ret_val from `xxx` where table_name = tableName for update;update `xxx` set current_value=current_value+step,next_value = next_value+step where table_name=tableName;

select for update，給這個表加了排它鎖，阻止其它事務取得相同數據集的共享讀鎖和排他寫鎖，同時，這個序列表表中，用來檢索的欄位沒有加索引，在 InnoDB 行鎖機制中：

由於 MySQL 的行鎖是針對索引加的鎖，不是針對記錄加的鎖，所以雖然是訪問不同行的記錄，但是如果是使用相同的索引鍵（在我們的場景中，就是查詢時用到的 table_name），是會出現鎖衝突的。

所以了解到其它團隊因為查詢這個表產生事務問題，造成死鎖，這個序列表被鎖住了。

由於這個自增序列表每個團隊都在使用，所以當時測試環境中，經常有 dao 層超時錯誤，最終將這些阻塞的線程 kill 掉，為序列表加了索引，解決了問題。

小結

下次遇到 MySQL 執行耗時的情況，排除了代碼問題之後，要去看資料庫是否有死鎖的情況存在，觀察有沒有被阻塞的線程，排查被阻塞的線程具體 info，定位到具體問題。

·END·

程序員的成長之路

路雖遠，行則必至

本文原發於 同名微信公眾號「程序員的成長之路」，回復「1024」你懂得，給個讚唄。

回復 [ 520 ] 領取程序員最佳學習方式

回復 [ 256 ] 查看 Java 程序員成長規劃


推薦閱讀：
相关文章