[
https://issues.apache.org/jira/browse/LOG4J2-2725?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17041150#comment-17041150
]
Nils Breunese commented on LOG4J2-2725:
---------------------------------------
It took us a couple of hours to find out that our increased load average was
caused by log4j 2.12.1, which was brought in by the upgrade from Spring Boot
2.1.x to 2.2.x. If this bug won't be fixed in log4j a 2.12.x update, then
Spring Boot 2.2.x users will not get this bugfix until they upgrade to Spring
Boot 2.3.0, which is currently scheduled for April 30, but that will probably
move into somewhere in May.
Sadly Spring Boot doesn't trust libraries to be backwards compatible across
different minor versions, so everyone using the latest Spring Boot 2.2.x will
be using log4j with this memory bug for a few more months. Of course individual
projects can override the log4j version, but then framework users like those
using Spring Boot first need to find out that they are dealing with a leaky
log4j version.
We also noticed that upgrading to log4j 2.13.0 fixed the load issue (no longer
a lot of
{{org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper}}
instances in memory), but also showed some weird behavior where multiple log
messages ended up in a single log line. We will need to investigate this
further, but this means upgrading is currently also not a way out for us.
Currently our best bet seems to downgrade to log4j 2.11.2 as used by Spring
Boot 2.1.x. So this is why I asked if it would be possible to backport this fix
to log4j 2.12.x. This would allow bringing this fix to everyone using log4j via
the current line of Spring Boot 2.2.x.
> RingBufferLogEvent.clear() is not called in case of OutOfMemoryError (or any
> other exception/error)
> ---------------------------------------------------------------------------------------------------
>
> Key: LOG4J2-2725
> URL: https://issues.apache.org/jira/browse/LOG4J2-2725
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.12.1
> Reporter: Dzmitry Anikechanka
> Priority: Major
> Labels: OOM
> Fix For: 2.13.0
>
> Attachments: RingBufferLogEvent_OOM.log,
> RingBufferLogEvent_dominator_tree.txt,
> domitator_tree_report_clear_called.txt,
> domitator_tree_report_clear_not_called.txt,
> image-2019-11-27-11-38-50-296.png, image-2019-11-27-11-39-49-904.png
>
> Time Spent: 1h 10m
> Remaining Estimate: 0h
>
> Please see the following class
> [https://logging.apache.org/log4j/2.x/log4j-core/apidocs/src-html/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.html]
> There is the following code in the onEvent() method:
> {code:java}
> event.execute(endOfBatch);
> event.clear();{code}
> But in case of an exception (or error) in the execute() method - method
> clear() will not be invoked, event will be not cleared (and logged message as
> well) and will be in the memory (probably try/catch will be enough to fix the
> issue).
> I've faced this issue when OutOfMemoryError occurred due to very large
> messages logging (also message is duplication in the SimpleMessage class,
> please see related issue https://issues.apache.org/jira/browse/LOG4J2-2724) -
> all these event are still in memory and it causes a lot of another OOM errors
> as memory is not released (because clear() method was not invoked).
> Please see attached [^RingBufferLogEvent_dominator_tree.txt] report from
> Eclipse Memory Analyzer ([https://www.eclipse.org/mat/]). As you can see
> there are a log of RingBufferLogEvent object that were not cleared and
> garbage collected:
> {code:java}
> Class Name
> | Shallow Heap | Retained Heap | Percentage
> ------------------------------------------------------------------------------------------------------------------------------------------
>
> | | |
> com.lmax.disruptor.RingBuffer @ 0x9f29a550
> | 144 | 1,205,392,112 | 57.52%
> '- java.lang.Object[262208] @ 0xb3d00000
> | 1,048,848 | 1,205,391,968 | 57.52%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0xa35f7f08
> | 104 | 233,251,104 | 11.13%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x8727b4d8
> | 104 | 185,151,488 | 8.84%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x8728ef48
> | 104 | 115,523,080 | 5.51%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x87264ae0
> | 104 | 83,109,992 | 3.97%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0xb1bd6950
> | 104 | 69,825,312 | 3.33%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x872730d0
> | 104 | 67,399,704 | 3.22%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x872651c8
> | 104 | 67,209,496 | 3.21%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x828e61d8
> | 104 | 48,321,480 | 2.31%
> |- org.apache.logging.log4j.core.async.RingBufferLogEvent @ 0x828ca708
> | 104 | 42,499,912 | 2.03%
> ................{code}
> Also please see [^RingBufferLogEvent_OOM.log] log file with OOM stacktrace:
> {code:java}
> java.lang.OutOfMemoryError: Java heap spacejava.lang.OutOfMemoryError: Java
> heap space at java.util.Arrays.copyOf(Arrays.java:3332) at
> java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:137)
> at
> java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:121)
> at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:421) at
> java.lang.StringBuilder.append(StringBuilder.java:136) at
> org.apache.logging.log4j.core.pattern.LineSeparatorPatternConverter.format(LineSeparatorPatternConverter.java:66)
> at
> org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> at
> org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
> at
> org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
> at
> org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
> at
> org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
> at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
> at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
> at
> org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:268)
> at
> org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
> at
> org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
> at
> org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:337)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:161)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745) {code}
> Could you please fix it or explain if such behavior is expected?
> Thanks,
> Dzmitry
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
