打日志还能出问题?记一次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<br></br> private static ThreadLocal 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问题。