作者：VipAugus

https://juejin.im/post/5ce906a3e51d455a2f2201dc

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+stepwhere table_name=tableName;

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

由于MySQL的行鎖是針對索引加的鎖，不是針對記錄加的鎖，所以雖然是訪問不同行的記錄，但是如果是使用相同的索引鍵（在我們的場景中，就是查詢時用到的table_name)，是會出現鎖沖突的。
所以了解到其它團隊因為查詢這個表產生事務問題，造成死鎖，這個序列表被鎖住了。Java提升篇－事務隔離級別和傳播機制Java提升篇－事務隔離級別和傳播機制
由于這個自增序列表每個團隊都在使用，所以當時測試環境中，經常有dao層超時錯誤，最終將這些阻塞的線程kill掉，為序列表加了索引，解決了問題。

小結

---

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

總結

以上是生活随笔為你收集整理的一条简单的 SQL 执行超过1000ms，纳尼？的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。