You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "ASF GitHub Bot (Jira)" <ji...@apache.org> on 2019/12/02 00:57:00 UTC
[jira] [Work logged] (LOG4J2-2725) RingBufferLogEvent.clear() is
not called in case of OutOfMemoryError (or any other exception/error)
[ https://issues.apache.org/jira/browse/LOG4J2-2725?focusedWorklogId=351679&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-351679 ]
ASF GitHub Bot logged work on LOG4J2-2725:
------------------------------------------
Author: ASF GitHub Bot
Created on: 02/Dec/19 00:56
Start Date: 02/Dec/19 00:56
Worklog Time Spent: 10m
Work Description: carterkozak commented on issue #317: LOG4J2-2725 - Added try/finally around event.execute() for RingBufferLogEventHandler
URL: https://github.com/apache/logging-log4j2/pull/317#issuecomment-560184283
Great find! Is there any chance we can test this? [EventParameterMemoryLeakTest](https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/test/java/org/apache/logging/log4j/core/EventParameterMemoryLeakTest.java) might provide some inspiration.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Issue Time Tracking
-------------------
Worklog Id: (was: 351679)
Time Spent: 0.5h (was: 20m)
> 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, 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: 0.5h
> 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)