背景

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

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

查找過程

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

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

而且此時去查看jvm參數(shù)已經(jīng)禁止顯示調用了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 突變前后內存增加值，發(fā)現(xiàn)增加的800M全部是byte[]，并且dump內存下來使用MAT查看內存，然后并沒有什么收獲。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

總結

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

主要有兩個坑：

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

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

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

好了，以上就是這篇文章的全部內容了，希望本文的內容對大家的學習或者工作具有一定的參考學習價值，如果有疑問大家可以留言交流，謝謝大家對腳本之家的支持。