[
https://issues.apache.org/jira/browse/LOG4J2-2725?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dzmitry Anikechanka updated LOG4J2-2725:
----------------------------------------
Description:
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
was:
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).
Could you please fix it or explain if such behavior is expected?
> 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
> Attachments: RingBufferLogEvent_OOM.log,
> RingBufferLogEvent_dominator_tree.txt
>
>
> 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)
