背景
一個服務(wù)突然所有機(jī)器開始頻繁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)系運(yùn)維告知那個時間點，我們所在的服務(wù)節(jié)點上部署了log_agent。
log_agent的作用就是把本地日志上報到日志中心存儲起來，其架構(gòu)示意圖demo如下：
猜著肯定是和log_agent通信的時候有bug導(dǎo)致的，于是讓運(yùn)維幫忙把其中一臺機(jī)器上的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)存存放新申請的對象，full gc沒有內(nèi)存碎片的問題，所以直接使用full gc回收的策略是合理的。
好了，以上就是這篇文章的全部內(nèi)容了，希望本文的內(nèi)容對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價值，如果有疑問大家可以留言交流，謝謝大家對服務(wù)器之家的支持。
原文鏈接：https://mp.weixin.qq.com/s/oBU0n0ajkjNfth-PuKQVRw
