記一次CMS GC耗時(shí)46.6秒的排查過(guò)程與解決方法
你知道的越多，不知道的就越多，業(yè)余的像一棵小草！
你來(lái)，我們一起精進(jìn)！你不來(lái)，我和你的競(jìng)爭(zhēng)對(duì)手一起精進(jìn)！
編輯：業(yè)余草
來(lái)源：juejin.cn/post/7257048145233543229
推薦：https://t.zsxq.com/11wE4iuIb
自律才 能自由
「早上7.16分左右」 ，有個(gè)服務(wù)發(fā)生了緊急告警，很多接口超時(shí)，出于 「客戶(hù)的投訴」 和老板的給出的壓力，我開(kāi)始了排查之旅~~~
?【排查到最后發(fā)現(xiàn)，并不是這些超時(shí)的接口都有問(wèn)題，而是 「其中某一個(gè)接口影響了整個(gè)服務(wù)」，只要是這個(gè)服務(wù)上的接口，都有可能超時(shí)、異常、 等不正?，F(xiàn)象】
?
看下現(xiàn)象
「釘釘群告警：」
釘釘群告警
「下圖為 告警機(jī)器JVM 監(jiān)控面板：」
JVM 監(jiān)控面板
觀察監(jiān)控面板看到的現(xiàn)象
「CMS GC單次耗時(shí)過(guò)長(zhǎng)：」
可以看到 CMS GC耗時(shí)46.6秒！ ，我們知道CMS收集器是作用于老年代的垃圾收集器，他有四個(gè)階段，其中階段1 （初始標(biāo)記）和階段4（重新標(biāo)記）會(huì)發(fā)生 「stop-the-world」（即暫停所有應(yīng)用線程），如果這 46.6 秒正好是這兩個(gè)階段中的某一個(gè)，那么，相當(dāng)于整個(gè)服務(wù)在這46.6秒內(nèi)，不處理任何的請(qǐng)求，只專(zhuān)注于垃圾回收的工作，整個(gè)服務(wù)高延遲，低吞吐！我去！那還怎么玩？？？這種情況下，該服務(wù)就算所有接口都超時(shí)，也不足為奇呀！
「線程數(shù)量：」 線程數(shù)量陡增
「線程狀態(tài)：」 waiting 和 time_waiting的線程陡增
「cpu情況：」 cpu使用率很高
觀察后得出結(jié)論 & 排查方向
- 一、「得出結(jié)論：」 觀察上邊的監(jiān)控信息，可以得出結(jié)論：
單次 CMS GC 耗時(shí)太長(zhǎng)！，線程，cpu 都不正常！ - 二、「排查方向：」 我的第一直覺(jué)就是有地方發(fā)生了內(nèi)存泄露（
因?yàn)閾?jù)我的經(jīng)驗(yàn)來(lái)看， 內(nèi)存泄露很有可能和 GC 相關(guān)聯(lián)），或者哪個(gè)地方分配了大對(duì)象。由于線程信息當(dāng)時(shí)沒(méi)有dump下來(lái)（不清楚啥原因沒(méi)搞下來(lái)），并且我猜測(cè)根因與 內(nèi)存泄露 或者 大對(duì)象分配 方面更接近，所以我的排查方向「沒(méi)往」 「線程」 那個(gè)方向走,而是 「著重觀察堆棧和GC信息」。
?光猜沒(méi)用呀，于是找運(yùn)維同學(xué)要了堆棧信息，之后的排查流程大概是這樣 ：
?
dump堆棧文件->使用 MAT 工具分析->仔細(xì)觀察各項(xiàng)指標(biāo) -> 定位問(wèn)題代碼
拿到堆棧文件并使用 MAT 分析
找運(yùn)維同學(xué)拿到堆棧信息文件 以.dump結(jié)尾的，如下：
MAT 分析
「拿到文件后解壓，并且后綴 改成 .hprof 否則mat工具不識(shí)別，導(dǎo)入不進(jìn)去?！?/strong>
說(shuō)到dump文件其實(shí)有很多個(gè)工具都可以分析，如下：
- 簡(jiǎn)易：JConsole、JVisualvm、HA、GCHisto、GCViewer
- 進(jìn)階：MAT、JProfiler
由于之前我使用過(guò)mat，所以我還是使用mat來(lái)排查，先簡(jiǎn)介下mat:
MAT（Eclipse Memory Analyzer）是一種快速且功能豐富的Java堆分析器，它幫助查找內(nèi)存泄漏。
使用內(nèi)存分析 器分析具有數(shù)億個(gè)對(duì)象的高效堆轉(zhuǎn)儲(chǔ)，快速計(jì)算對(duì)象的保留大小，查看誰(shuí)在阻止垃圾收集器收集對(duì)象，
運(yùn)行報(bào)告以自動(dòng)提取泄漏嫌疑。 官網(wǎng)地址https://www.eclipse.org/mat，
下載地址為https://www.eclipse.org/mat/downloads.php。我們可以在下載 頁(yè)面看到：MAT可以獨(dú)立運(yùn)行，
也可以通過(guò)插件的形式在Eclipse中安裝使用，具體的安裝過(guò)程就不再這里介紹了，我是下載的獨(dú)立運(yùn)行 的程序包。
導(dǎo)入：
導(dǎo)入分析
導(dǎo)入后，一般都會(huì)自動(dòng)分析，需要一定時(shí)間，分析完后如下：
自動(dòng)分析
看懂 MAT工具 的分析報(bào)告
?工欲善其事必先利其器，接下來(lái)我們看看這個(gè)工具的一些常用操作，以及分析了哪些指標(biāo)？
?
「Histogram：」 直方圖(里邊包含了每個(gè)類(lèi)所對(duì)應(yīng)的對(duì)象個(gè)數(shù)，以及所占用的內(nèi)存大小)
分析報(bào)告
「Dominator Tree：」 可以看到哪些對(duì)象占用的空間最大以及占比 (常用于尋找大對(duì)象)
Dominator Tree
「Leak Suspects：」 可疑的內(nèi)存泄露 分析，餅狀圖很直觀（排查內(nèi)存泄露利器）。
Leak Suspects
Top components：** 對(duì)占用 堆內(nèi)存 超過(guò) 整個(gè)堆內(nèi)存1% 大小的組件做的一系列分析
可以看到他是從多個(gè)角度（如：對(duì)象，類(lèi)加載器，包）來(lái)分析占比超過(guò)1%的組件的。
Top components
Top consumers：** 列出最昂貴的對(duì)象
Top consumers
可以看到 Top components和Top consumers 差不多，區(qū)別似乎不是很大。
「Component Report」 組件的一些報(bào)告（分析屬于公共根包或類(lèi)加載器的對(duì)象）
「Duplicate Classes」 用來(lái)查找重復(fù)的類(lèi)
其中 Component Report 和 Duplicate Classes 我個(gè)人認(rèn)為不常用，不再過(guò)多介紹。
在排查分析時(shí)候，我認(rèn)為 「Histogram」 ，「Leak Suspects」，「Dominator Tree」，「Top Consumers」，「Top Components」，這些都得好好觀察下，越多觀察，答案就會(huì)離你越近。
mat觀察到的結(jié)果
Histogram 結(jié)果：
Histogram
由于 Histogram 是列出每個(gè)類(lèi)所對(duì)應(yīng)的對(duì)象個(gè)數(shù)，以及所占用的內(nèi)存大小，所以一般比較基礎(chǔ)的類(lèi)，對(duì)象都比較多，這也是正?，F(xiàn)象，比如（基本類(lèi)型數(shù)組，以及String， map， list 等各種集合以及 Java中的一些自帶的類(lèi)），但是其中一個(gè)值的注意 就是com.mysql,jdbc.ByteArrayRow 這個(gè)類(lèi)很顯眼，看起來(lái)就是邏輯上的一行數(shù)據(jù)，這個(gè)類(lèi)的對(duì)象這么多，不禁讓我起疑了，ok , 下邊繼續(xù)看其他維度的分析結(jié)果。
Dominator Tree 結(jié)果
可以清楚的看到，其中某個(gè)arrayList占到了 整個(gè)堆的 56.90% 說(shuō)明有大對(duì)象出現(xiàn)了。(list里邊的對(duì)象其實(shí)就是 com.mysql,jdbc.ByteArrayRow ！)
Dominator Tree
Leak Suspects 結(jié)果
Leak Suspects
上邊截圖告訴我們可能存在內(nèi)存泄露，于是我追蹤一下，點(diǎn)擊 「outgoing references」 （說(shuō)明：outgoing references 應(yīng)該是可以觀察到這個(gè)線程內(nèi)，大概都做了哪些事情，或者可以簡(jiǎn)單粗暴理解為 這個(gè)線程都引用了哪些對(duì)象） ，結(jié)果如下：
Leak Suspects 結(jié)果
ps: 由于 Top Consumers 和 Top Components 的分析結(jié)果與 Dominator Tree 的 「結(jié)果很像」 我就不貼出來(lái)了。
定位到問(wèn)題和代碼片段
從 Histogram，Dominator Tree，Leak Suspects 三項(xiàng)指標(biāo)分析得出 「本次問(wèn)題的原因」：
「某個(gè)sql查詢(xún)出了幾百萬(wàn)條數(shù)據(jù)（幾百萬(wàn)個(gè)ByteArrayRow對(duì)象），導(dǎo)致list集合占到堆內(nèi)存的56.90%（導(dǎo)致GC出現(xiàn)問(wèn)題）」
?說(shuō)明：遺憾的是沒(méi)有拿到GC日志，只能從監(jiān)控面板和mat工具觀察：正向（jvm監(jiān)控）+反向（mat得出結(jié)果），來(lái)證實(shí)是GC問(wèn)題，而不能從GC日志直接入手。
?
代碼一覽
ok，到這里其實(shí)我已經(jīng)根據(jù)mat中的sql：
代碼一覽
找到代碼片段了，代碼如下：
看到這個(gè)代碼，我思緒萬(wàn)千。。。。。一時(shí)不知如何言語(yǔ)。。。。
條件是空，不就是select a,b,c from tableA where 1=1 了？這不就是全表掃描了嗎 ，殘酷，無(wú)情。。。
解決
解決辦法 so easy 將 1=1 去掉，并且把 if 判斷也去掉，傳進(jìn)來(lái)的條件為null時(shí)，拿null去匹配，然后結(jié)果返回的也是空就完事了（因?yàn)樵撟侄问潜厝徊皇强盏模?/p>
總結(jié)
-
首先本次排查過(guò)程，借助兩大工具，一個(gè)就是
jvm監(jiān)控也即：Prometheus+ grafana通過(guò)這倆兄弟的組合，我們可以觀察到j(luò)vm情況，直觀的看出服務(wù)是否有異常。 -
第二就是
dump堆棧文件，因?yàn)閖vm監(jiān)控面板gc及其不正常，所以順藤摸瓜找到堆棧信息 (這里謝謝運(yùn)維同學(xué))，并通過(guò)mat工具分析，然后找到可疑地方，不得不說(shuō)此次排查還算比較順利，直接找到了問(wèn)題點(diǎn)以及sql語(yǔ)句都找出來(lái)了，這樣更快速的定位了問(wèn)題代碼。 -
說(shuō)明：由于本篇文章關(guān)注實(shí)際排查過(guò)程，對(duì)cms gc知識(shí)未做過(guò)多展開(kāi)。另外本次的小遺憾就是沒(méi)有拿到 GC 日志，下次出現(xiàn)問(wèn)題第一時(shí)間要GC日志以及堆棧信息和線程文件 「統(tǒng)統(tǒng)都要」 哈哈~ 。
-
「結(jié)論（重要）：」 雖然沒(méi)拿到GC日志，但是通過(guò)我個(gè)人的經(jīng)驗(yàn)來(lái)說(shuō)，可以基本確定本次告警的原因 即：
?
間接原因：
由于全表掃描，返回幾百萬(wàn)數(shù)據(jù)（全部緩存在了內(nèi)存中）直接原因：
?由于內(nèi)存中數(shù)據(jù)過(guò)多，在CMS GC 的Final Remark（重新標(biāo)記階段）這個(gè)耗時(shí)就會(huì)很長(zhǎng)（我猜測(cè)這個(gè)重新標(biāo)記 耗時(shí)正好是監(jiān)控看到的46.6秒，或者比這個(gè)值小點(diǎn)），并且這個(gè)重新標(biāo)記階段是Stop The World，也就是說(shuō)在一段時(shí)間內(nèi)服務(wù)將暫停所有的工作線程，也就導(dǎo)致了服務(wù)吞吐下降，大量接口超時(shí)的現(xiàn)象了~
千里之行始于足下，其實(shí)工作久了就會(huì)發(fā)現(xiàn)，很多看似很?chē)?yán)重的問(wèn)題，其實(shí)最后排查到的問(wèn)題點(diǎn)，都是一個(gè)很基礎(chǔ)的東西，或者說(shuō)一個(gè)很簡(jiǎn)單的東西引起的。就比如這次這個(gè)sql的書(shū)寫(xiě) 真的是很基礎(chǔ)很基礎(chǔ)了，但是就是這么基礎(chǔ)的東西，一不留心就會(huì)全表掃描，小表沒(méi)事，大表的話返回幾百萬(wàn)，甚至幾千萬(wàn)幾億的數(shù)據(jù)，那接口還不超時(shí)？服務(wù)還不宕機(jī)？所以敬畏每一行代碼，把每一件小事做好，就是我追求的目標(biāo)。