背景

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

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

查找過程

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

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

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

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

想著要是能找到gc的原因就好了。于是使用 jstat -gccause實(shí)時(shí)監(jiān)控gc原因，但是發(fā)現(xiàn)始終是Allocation Failure。但是在監(jiān)控中發(fā)現(xiàn)old區(qū)域中有突然增加800M，通過我司的監(jiān)控平臺(tái)也發(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)存，然后并沒有什么收獲。

第三、找到有問題開始時(shí)候的改動(dòng)點(diǎn)

因?yàn)轫?xiàng)目在發(fā)生問題的時(shí)候并沒有改動(dòng)和上線，基本上就排除代碼本身的原因。聯(lián)系運(yùn)維告知那個(gè)時(shí)間點(diǎn)，我們所在的服務(wù)節(jié)點(diǎn)上部署了log_agent。

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

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

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

第四、定位日志上報(bào)的jar具體有問題的代碼

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

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

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

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

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

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

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

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

總結(jié)

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

主要有兩個(gè)坑：

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

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

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

好了，以上就是這篇文章的全部?jī)?nèi)容了，希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，如果有疑問大家可以留言交流，謝謝大家對(duì)腳本之家的支持。

最新評(píng)論