最近線上系統(JDK1.7)出現了多次FullGC,但是情況都不一樣,今天有時間,將FullGC的排查思路以及如何解決記錄下,供大家一起探討。
場景一:
系統發布上線之后,里面收到如下告警信息:
內容:計算周期:2019-11-15 00:16:00-18:00,節點:*.*.*.*,FullGC次數:63次(大於閾值:10次),已觸發嚴重告警!
收到上述告警信息之后,第一反應就是代碼新發布的功能有問題;但是由於當天發布功能有點多,一時半會無法定位到是哪個功能引起的,因此從功能點排查引起FullGC有點難度;
換個角度,既然發生了FullGC,無外乎幾種情況:
- 代碼中顯示調用System.gc();
- jvm的堆空間不足
- jvm的永久代空間不足
依據上述內容,先按照關鍵字gc()排查代碼,發現代碼中存在一個批量導出的功能,在for循環中每次都有顯示調用,通過功能驗證,發現每次代碼執行到這里時都會收到告警信息;同時再次排查每次FullGC時jvm堆變換情況:
通過JVM內存使用情況可以確認,本次FullGC,PermGen、OldGen回收效率均為0%,說明雖然觸發了FullGC但是由於並未到達上述2/3兩種原因,因此可以再次確認是由於代碼中顯示調用System.gc引起的,在把代碼注釋掉之后再次驗證,未出現FllGC情況;
場景二:
場景一問題解決之后,過了2天,系統突然間又發生類似的情況,再次排查代碼,發現系統中所有gc()關鍵字均沒有了,此時無法確認問題原因。
為了明確該問題的原因,從服務器上導出gc的詳細日志
2019-11-26T17:04:52.849+0800: 669022.072: [Full GC (System.gc()) 580M->409M(4096M), 1.2260290 s
通過日志分析,發生FullGC的時候,依然是由於System.gc()導致的,但是代碼中卻沒有,因此還需要分析所有請求,通過告警信息發現,所有告警均出現在2分鍾之內,因此可以斷定應該是跟某個功能相關,因此按照時間節點過濾這2分鍾內容所有請求,通過對比發現,所有發生異常情況下均有一個業務請求在執行,通過代碼分析發現這個請求是一個excel導入請求,為了明確此次fullGC的根本原因,需要導出javacore(線程快照)
通過分析快照日志發現:
線程中存在System.gc()方法,通過代碼查看,在excel導入過程中使用了jxl組件,該組件中存在兩個方法
上述兩處均存在現實調用System.gc(),雖然有gcDisabled屬性控制,但是通過代碼排查發現未設置該屬性,某人為false,因此只要使用到上述兩個方法,均會觸發FllGC。
因此建議不要在使用jxl組件,改為poi組件,或者在使用jxl組件時顯示設置gcDisabled屬性即可。
場景三:
該場景跟上述都不一樣,在系統運行一段時間之后,突然短時間內發生接口出現嚴重超時的情況,此時通過監控系統查看jvm堆情況,
發現OldGen已經快滿了,因而觸發FullGC,但是定位是由於什么觸發GC,還是花費了一番功夫。
還是從日志下手,在出現FullGC的時候,發現在jvm中存在大量
org.apache.xmlbeans.impl.store.Xobj$AttrXobj
org.apache.xmlbeans.impl.store.Xobj$ElementXobj
說明,系統中大概率存在操作poi,因此迅速排查poi關鍵字,逐個方法排查(問題發生已經超過2小時還未定位到到問題,此時心里已經是萬分着急,但是再着急也需要平和心態,從已經日志和現象中逐一查找,不能隨意猜測,此時的任何猜測均會引導你進入另一個歧途),發現在一個批量導入的場景中,存在如下代碼:
上述代碼的本意是將excel中的所有空行過濾掉,對於一個正常的excel是沒有任何問題,但是如果是這樣的一個excel文件,就可能會出現問題:
通過圖中可以發現,該excel居然被創造出了100w行的空行,雖然通過上面的空過濾可以將這100w行過濾掉,但是不可忽視的是我們會創造近100w個Row對象,且這些對象在短時間內不能被垃圾回收,當程序執行完畢后,由於對象過大就會觸發FullGC,導致發生Stop World,因此此時當前jvm的其他服務也會出現大量超時。
因此在處理excel的時候,務必先判斷總行數、總大小,在做明細判斷。
通過上述三個FullGC的處理場景,發現在發生FullGC的時候,大概率是跟我們代碼編寫有關,因此如何能夠熟練使用各種java命令、以及日志分析,對我們能夠快速定位問題是很有幫助的。
同時此處在跟大家分享一個個人心得:所有問題排查均需要建立在對業務十分熟悉的情況下,否則將會走很多彎路,因此建議大家不要單純盲目迷戀技術,業務+技術才是我們立足的資本。