記一次log4j日誌致使線上OOM問題案例

最近一個服務忽然出現 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問題。