作者：VipAugus

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

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

大概過程

---

在測試環(huán)境Docker容器中，在跨進程調(diào)用服務(wù)的時候，A應(yīng)用通過Dubbo調(diào)用B應(yīng)用的RPC接口，發(fā)現(xiàn)B應(yīng)用接口超時錯誤，接著通過debug和日志，發(fā)現(xiàn)具體耗時的地方在于一句簡單SQL執(zhí)行，但是耗時超過1000ms。

通過查看數(shù)據(jù)庫的進程列表，發(fā)現(xiàn)是有死鎖鎖表了，很多進程狀態(tài)status處于'sending data'，最后為鎖住的表添加索引，并且kill掉阻塞的請求，解除死鎖，服務(wù)速度恢復(fù)正常。

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

通過觀察業(yè)務(wù)代碼，確認沒有內(nèi)存溢出或者其它事務(wù)問題，于是只能考慮Docker環(huán)境的數(shù)據(jù)庫和jvm底層詳情了。

使用Druid監(jiān)控SQL執(zhí)行狀態(tài)

---

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

于是打算使用阿里巴巴的數(shù)據(jù)庫連接池Druid進行監(jiān)控，監(jiān)控SQL效果如下：

在SQL監(jiān)控Tab中，可以看到執(zhí)行SQL的具體情況，包括某條SQL語句執(zhí)行的時間（平均、最慢）、SQL執(zhí)行次數(shù)、SQL執(zhí)行出錯的次數(shù)等。
上面顯示的是正常情況下，時間單位是ms，正常的SQL一般在10ms之內(nèi)，數(shù)據(jù)量大的控制在30ms之內(nèi)，這樣用戶的使用體驗感才會良好。所以說之前的1000ms，是不可接受的結(jié)果。

通過JMC遠程監(jiān)控Tomcat

---

JMC(java mission control)是jdk自帶的一個監(jiān)控工具，在jdk的bin目錄下（java大法好，該目錄下有很多實用的工具）。
此處加了一個tomcat無驗證模式：

• #在tomcat的conf目錄下的catalina.sh增加如下java啟動參數(shù)：-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

下面是自己本地調(diào)試的截圖

然后打開jmc，創(chuàng)建一個JMX連接，輸入對應(yīng)的ip和JMX端口。接著可以設(shè)定一段時間內(nèi)的飛行監(jiān)控，監(jiān)測這一分鐘內(nèi)jvm具體參數(shù)
當時調(diào)試的時候，發(fā)現(xiàn)內(nèi)存使用、CPU占用率、線程狀態(tài)也挺正常的，沒有發(fā)現(xiàn)明顯的異常錯誤，效果如下圖：

唯一比較耗時的是在代碼tab頁中，當時發(fā)現(xiàn)了大量的I/O，比上圖的比例還高，當時大概占了80%，查看調(diào)用樹，很多循環(huán)tcp socket連接，考慮到應(yīng)用中本來就有很多需要io以及netty也需要tcp連接，所以大概排除了jvm虛擬機的問題，然后就去排查MySQL的問題。

排查MySQL

---

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

直接執(zhí)行SQL語句

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

查看MySQL線程列表

• show processlist;

從圖中可以看出，有些線程的狀態(tài)處于sending data，查閱資料：所謂的“Sending data”并不是單純的發(fā)送數(shù)據(jù)，而是包括“收集 + 發(fā)送 數(shù)據(jù)”。
然后后面一列info顯示的是具體信息，是查詢用來生成主鍵ID的函數(shù)，之前速度都很快，為啥突然就這么慢呢，于是回過頭去查看該函數(shù)：

• 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，給這個表加了排它鎖，阻止其它事務(wù)取得相同數(shù)據(jù)集的共享讀鎖和排他寫鎖，同時，這個序列表表中，用來檢索的字段沒有加索引，在InnoDB行鎖機制中：

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

小結(jié)

---

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

總結(jié)

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

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。