记一次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问题。