點(diǎn)擊上方“終端研發(fā)部”，選擇“星標(biāo)”

回復(fù)“資源”，領(lǐng)取全網(wǎng)最火的Java核心知識(shí)總結(jié)~

正文

大概過程

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

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

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

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

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

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

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

在SQL監(jiān)控Tab中，可以看到執(zhí)行SQL的具體情況，包括某條SQL語(yǔ)句執(zhí)行的時(shí)間（平均、最慢）、SQL執(zhí)行次數(shù)、SQL執(zhí)行出錯(cuò)的次數(shù)等

上面顯示的是正常情況下，時(shí)間單位是ms，正常的SQL一般在10ms之內(nèi)，數(shù)據(jù)量大的控制在30ms之內(nèi)，這樣用戶的使用體驗(yàn)感才會(huì)良好。

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

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

J****MC(java mission control)是jdk自帶的一個(gè)監(jiān)控工具，在jdk的bin目錄下（java大法好，該目錄下有很多實(shí)用的工具）。

此處加了一個(gè)tomcat無(wú)驗(yàn)證模式：

#在tomcat的conf目錄下的catalina.sh增加如下java啟動(dòng)參數(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)建一個(gè)JMX連接，輸入對(duì)應(yīng)的ip和JMX端口。

接著可以設(shè)定一段時(shí)間內(nèi)的飛行監(jiān)控，監(jiān)測(cè)這一分鐘內(nèi)jvm具體參數(shù)

當(dāng)時(shí)調(diào)試的時(shí)候，發(fā)現(xiàn)內(nèi)存使用、CPU占用率、線程狀態(tài)也挺正常的，沒有發(fā)現(xiàn)明顯的異常錯(cuò)誤，效果如下圖：

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

排查MySQL

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

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

查看MySQL線程列表

show processlist;

從圖中可以看出，有些線程的狀態(tài)處于sending data，查閱資料：所謂的“Sending data”并不是單純的發(fā)送數(shù)據(jù)，而是包括“收集 + 發(fā)送 數(shù)據(jù)”。

然后后面一列info顯示的是具體信息，是查詢用來(lái)生成主鍵ID的函數(shù)，之前速度都很快，為啥突然就這么慢呢，于是回過頭去查看該函數(shù)：

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

select for update，給這個(gè)表加了排它鎖，阻止其它事務(wù)取得相同數(shù)據(jù)集的共享讀鎖和排他寫鎖，同時(shí)，這個(gè)序列表表中，用來(lái)檢索的字段沒有加索引，在InnoDB行鎖機(jī)制中：

由于MySQL的行鎖是針對(duì)索引加的鎖，不是針對(duì)記錄加的鎖，所以雖然是訪問不同行的記錄，但是如果是使用相同的索引鍵（在我們的場(chǎng)景中，就是查詢時(shí)用到的table_name)，是會(huì)出現(xiàn)鎖沖突的。

所以了解到其它團(tuán)隊(duì)因?yàn)椴樵冞@個(gè)表產(chǎn)生事務(wù)問題，造成死鎖，這個(gè)序列表被鎖住了。

由于這個(gè)自增序列表每個(gè)團(tuán)隊(duì)都在使用，所以當(dāng)時(shí)測(cè)試環(huán)境中，經(jīng)常有dao層超時(shí)錯(cuò)誤，最終將這些阻塞的線程kill掉，為序列表加了索引，解決了問題。

小結(jié)

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

出處：https://juejin.im/post/5ce906a3e51d455a2f2201dc

編輯：尹文敏

2019,我遲來(lái)的總結(jié)

為什么說重啟能解決90%的問題

重磅！Tomcat 爆出高危漏洞，你升級(jí)了沒？

32歲程序員，失業(yè)4個(gè)月45次面試經(jīng)歷，與君共勉

重磅！Android Studio 3.6 發(fā)布,究竟有什么新功能？

IntelliJ IDEA 快捷鍵終極大全，速度收藏！

相信自己，沒有做不到的，只有想不到的

在這里獲得的不僅僅是技術(shù)！

喜歡就給個(gè)“在看”

總結(jié)

以上是生活随笔為你收集整理的服务器执行MySQL耗时问题解决全过程的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

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