full gc查找問題的示例分析

這篇文章給大家分享的是有關(guān)full gc查找問題的示例分析的內(nèi)容。小編覺得挺實用的，因此分享給大家做個參考，一起跟隨小編過來看看吧。

背景

一個服務(wù)突然所有機器開始頻繁full gc。而服務(wù)本身沒有任何改動和發(fā)布記錄。上線查看gc log日志，日志如下：

從日志來看，每次發(fā)生full gc的時候都比較奇怪，主要有兩點，第一、old區(qū)域和perm的區(qū)域使用率很低，沒有到達(dá)觸發(fā)full gc的條件，第二、項目中配置的是CMS，為什么沒有進(jìn)行 CMS GC，直接進(jìn)行了full gc呢。

查找過程

第一、代碼會不會是調(diào)用了System.gc()

考慮在使用direct memory的時候，先判斷direct memory是否足夠，要是不足的話會使用System.gc()嘗試釋放內(nèi)存。于是直接使用反射去監(jiān)控direct memory。發(fā)現(xiàn)direct memory的使用率始終在10%左右，不可能去調(diào)用System.gc()。

而且此時去查看jvm參數(shù)已經(jīng)禁止顯示調(diào)用了System.gc()了。

第二、使用 jstat -gccause查看gc原因

想著要是能找到gc的原因就好了。于是使用 jstat -gccause實時監(jiān)控gc原因，但是發(fā)現(xiàn)始終是Allocation Failure。但是在監(jiān)控中發(fā)現(xiàn)old區(qū)域中有突然增加800M，通過我司的監(jiān)控平臺也發(fā)現(xiàn)了old區(qū)域暴漲的現(xiàn)象。監(jiān)控如下：

并且通過jmap -histo pid查看old Gen 突變前后內(nèi)存增加值，發(fā)現(xiàn)增加的800M全部是byte[]，并且dump內(nèi)存下來使用MAT查看內(nèi)存，然后并沒有什么收獲。

第三、找到有問題開始時候的改動點

因為項目在發(fā)生問題的時候并沒有改動和上線，基本上就排除代碼本身的原因。聯(lián)系運維告知那個時間點，我們所在的服務(wù)節(jié)點上部署了log_agent。

log_agent的作用就是把本地日志上報到日志中心存儲起來，其架構(gòu)示意圖demo如下：

猜著肯定是和log_agent通信的時候有bug導(dǎo)致的，于是讓運維幫忙把其中一臺機器上的log_agent給刪除了，刪除之后full gc恢復(fù)正常。

到此基本上確定了是日志上報導(dǎo)致的問題。

第四、定位日志上報的jar具體有問題的代碼

定位到是日志上報的jar導(dǎo)致的問題之后，就把這個問題反饋給了相關(guān)負(fù)責(zé)人。但是他們追蹤了很久之后并沒有發(fā)現(xiàn)什么問題。

之后有時間之后，我就把他們相關(guān)代碼看了一下，發(fā)現(xiàn)其中有段代碼有點問題。有問題代碼如下：

在出入log的的時候在append中會調(diào)用sendLogEntry這個方法，而logEntries本身是個list對象，非線程安全的。這樣的話，在多個線程中同時輸出日志就有安全問題。于是就在sendLogEntry這個方法上加上線程安全（synchronized），上線問題解決，沒有發(fā)生頻繁full gc了。

但是多線程下同時調(diào)用list也不應(yīng)該頻繁full gc啊，這個地方有bug，但是不應(yīng)該導(dǎo)致頻繁 full gc。我懷疑是client.Log(logEntries); 這個方法本身不是線程安全的。以為我把線程同步塊鎖在了client.Log(logEntries);這個代碼塊上。發(fā)現(xiàn)問題也得以解決。

client.Log的代碼就是一個發(fā)送相關(guān)日志、并接收返回值進(jìn)行確認(rèn)，使用的是thrift框架進(jìn)行通信的。于是在接收返回值的地方，給加了點log。代碼如下：

從日志中我們可以看到，從返回值中讀取的字節(jié)流大小最大達(dá)1.2G甚至1.8G，這很明顯不正常啊。因為young Gen 1.5G，old Gen 1G，必定會拋OOM。而在最上層捕獲了error，但是默認(rèn)情況下卻沒有l(wèi)og，導(dǎo)致log中看不出任何問題。

回想起我司RPC服務(wù)也是用的thrift是用的連接池的方式，所以client肯定是非線程安全的。

問題定位到之后，準(zhǔn)備反饋給那個人。發(fā)現(xiàn)那個人已經(jīng)離職了。于是嘗試升級到最新的jar之后，發(fā)現(xiàn)他們在sendLogEntry這個方法上加上了synchronized。

總結(jié)

上面給出了總結(jié)后應(yīng)該遵循的定位問題步驟。真實的查找過程絕不是按照上面的那個過程來的，這個問題的追查持續(xù)了大概兩周（每天投入1-2個小時左右吧？）。

主要有兩個坑：

gc log。開始的時候關(guān)注點一直在gc log上。從gc log來看根本不滿足發(fā)生full gc的條件。于是專注點在認(rèn)為引入的jar有在調(diào)System.gc()并沒有注意到這個-XX:+DisableExplicitGC參數(shù)

對Error的處理。我司日志中心提供的jar居然直接忽略了Error導(dǎo)致了OOM日志一直沒有顯示出來，不然問題發(fā)生時肯定就能直接定位到了。

JVM拋出OOM之后，就算配置的是CMS，JVM仍舊是使用的Full GC來回收內(nèi)存。因為CMS會有內(nèi)存碎片化問題，已經(jīng)發(fā)生了OOM，可能是因為沒有連續(xù)內(nèi)存存放新申請的對象，F(xiàn)ull GC沒有內(nèi)存碎片的問題，所以直接使用Full GC回收的策略是合理的。

感謝各位的閱讀！關(guān)于“full gc查找問題的示例分析”這篇文章就分享到這里了，希望以上內(nèi)容可以對大家有一定的幫助，讓大家可以學(xué)到更多知識，如果覺得文章不錯，可以把它分享出去讓更多的人看到吧！