记一次log4j日志导致线上OOM问题案例
最近一个服务突然出现 OutOfMemoryError,两台服务因为这个原因挂掉了,一直在full gc。还因为这个问题我们小组吃了一个线上故障。很是纳闷,一直运行的好好的,怎么突然就不行了呢。。。
配置了一个 -XX:+HeapDumpOnOutOfMemoryError(该参数作用是在第一次发生OOM错误时候会打印dump内存信息),便开始通过dump文件开始查找问题。
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问题。