记一次log4j日志导致线上OOM问题案例

水深无声 2024-03-17 16:42 90阅读 0赞

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

![1688734429698][]

为什么一个dubbo线程会占用这个大的内存呢，很是奇怪，节点打开一个具体线程信息看到，

![img][]

一个dubbo线程是有一个threadlocal对象，threadlocal对象里面引用了一个java StringBuilder对象，改对象有char数组6百多万，占用内存12M。

通过ThreadLocalMap$Entry对象里referent属性找到引用ThreadLocal对象:

![img][img 1]

看到这里，觉得有点希望了，继续打开代码搜索log4j中ParameterizedMessage类，看到里面有一行代码：

// storing JDK classes in ThreadLocals does not cause memory leaks in web apps, so this is okay  
  
private static ThreadLocal threadLocalStringBuilder = new ThreadLocal<>();  
这个StringBuilder不就是上面看到打对象吗，知道了这个对象，接下来就是看这个ThreadLocal是怎么使用的啦。

继续查看log4j + Disurptor源码。。。

发现在打日志代码中，RingBufferLogEvent中setMessage方法会进行打印日志的一个格式化，

![img][img 2]

继续跟进去，看看格式化具体做了什么即 ParameterizedMessage.getFormattedmessage()方法

![img][img 3]

问题就出在这个方法里，方法是从当前线程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()这个方法：

![img][img 4]

发现只多了一行代码，继续看：

![img][img 5]

这里回判断如果stringbuilder不为null并且容量大于maxSize（这个参数可配，默认518），会将长度置为maxSize，然后调用trimToSize方法，

![img][img 6]

刚方法就是将原char数组进行了一次copy，copy了一个maxSize大小的数组。

这样即就是每次格式化之后会进行一次判断，如果对象ThreadLocal stringbuilder对象太大会将该对象重新copy一个固定大小，避免老版本出现OOM问题。

[1688734429698]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/5dbfc5a9332b466c95f67dd0bf4cc098.png
[img]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/d94495e459a34155b06810a382f573a3.png
[img 1]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/2eb15a8aabad4a12962444779a99f2e9.png
[img 2]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/953f3dcceac24810b25ae823c67ebc2d.png
[img 3]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/c42818fa9e3149e981abcb309ea5bc04.png
[img 4]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/097386cd86084408b6ebe1f540102ec4.png
[img 5]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/40f6c27f1fe14ab88531691d2e9cd445.png
[img 6]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/15/e7a1cebd73974e6b9618c6b3d5916448.png