最近一個服務突然出現 OutOfMemoryError,兩台服務因為這個原因掛掉了,一直在full gc。還因為這個問題我們小組吃了一個線上故障。很是納悶,一直運行的好好的,怎么突然就不行了呢。。。
配置了一個 -XX:+HeapDumpOnOutOfMemoryError(該參數作用是在第一次發生OOM錯誤時候會打印dump內存信息),便開始通過dump文件開始查找問題。
項目各項環境參數:
項目使用dubbo框架,dubbo線程池配置500
項目內存配置2G,old區1.5G
項目使用 Log4j + Disruptor 實現的異步記錄日志
log4j-api版本2.6.2 log4j-core版本2.6.2
disruptor版本3.3.6
問題分析:
都知道發生OOM問題是因為內存不夠,造成原因卻有很多。具體的場景具體分析,通過gc日志發現每次full gc回收的內存越來越少,造成最后OutOfMemoryError: GC overhead limit exceeded。
通過Java MAT工具分析dump發現,一個最大dubbo線程占用內存12M,總的dubbo線程占用內存加起來都已經1.6G了。
為什么一個dubbo線程會占用這個大的內存呢,很是奇怪,節點打開一個具體線程信息看到,
一個dubbo線程是有一個threadlocal對象,threadlocal對象里面引用了一個java StringBuilder對象,改對象有char數組6百多萬,占用內存12M。
通過ThreadLocalMap$Entry對象里referent屬性找到引用ThreadLocal對象:
看到這里,覺得有點希望了,繼續打開代碼搜索log4j中ParameterizedMessage類,看到里面有一行代碼:
// storing JDK classes in ThreadLocals does not cause memory leaks in web apps, so this is okay
private static ThreadLocal<StringBuilder> threadLocalStringBuilder = new ThreadLocal<>();
這個StringBuilder不就是上面看到打對象嗎,知道了這個對象,接下來就是看這個ThreadLocal是怎么使用的啦。
繼續查看log4j + Disurptor源碼。。。
發現在打日志代碼中,RingBufferLogEvent中setMessage方法會進行打印日志的一個格式化,
繼續跟進去,看看格式化具體做了什么即 ParameterizedMessage.getFormattedmessage()方法
問題就出在這個方法里,方法是從當前線程ThreadLocal里面拿到StringBuilder對象,然后每次將length置0,然后將日志append進去
所以從這里就知道,只要有一次日志內容打印很多情況下,會造成StringBuilder里字段串對象很大,而且是不會銷毀(除非當前ThreadLocal線程死了,前面說了項目配置了dubbo 500個線程,dubbo線程不死,所以這個對象一直都在),打印大日志對象次數多了,基本上造成所有dubbo線程ThreadLocal StringBuilder對象都很大。正如第一幅圖看到一樣,最終造成OOM。
log4j 2.6.2這里進行日志格式化,打印日志內容過大時候確實會造成這個問題
然后拉取了下log4j新一些的,發現在log4j 在2.9.0版本解決了這個問題,如何解決的呢,具體來看看代碼吧,還是ParameterizedMessage.getFormattedmessage()這個方法:
發現只多了一行代碼,繼續看:
這里回判斷如果stringbuilder不為null並且容量大於maxSize(這個參數可配,默認518),會將長度置為maxSize,然后調用trimToSize方法,
剛方法就是將原char數組進行了一次copy,copy了一個maxSize大小的數組。
這樣即就是每次格式化之后會進行一次判斷,如果對象ThreadLocal stringbuilder對象太大會將該對象重新copy一個固定大小,避免老版本出現OOM問題。