full gc查找問題的示例分析

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

背景

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

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

查找過程

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

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

而且此時去查看jvm參數已經禁止顯示調用了System.gc()了。

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

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

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

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

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

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

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

到此基本上確定了是日志上報導致的問題。

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

定位到是日志上報的jar導致的問題之后，就把這個問題反饋給了相關負責人。但是他們追蹤了很久之后并沒有發現什么問題。

之后有時間之后，我就把他們相關代碼看了一下，發現其中有段代碼有點問題。有問題代碼如下：

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

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

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

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

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

問題定位到之后，準備反饋給那個人。發現那個人已經離職了。于是嘗試升級到最新的jar之后，發現他們在sendLogEntry這個方法上加上了synchronized。

總結

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

主要有兩個坑：

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

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

JVM拋出OOM之后，就算配置的是CMS，JVM仍舊是使用的Full GC來回收內存。因為CMS會有內存碎片化問題，已經發生了OOM，可能是因為沒有連續內存存放新申請的對象，Full GC沒有內存碎片的問題，所以直接使用Full GC回收的策略是合理的。

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