Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2725

RingBufferLogEvent.clear() is not called in case of OutOfMemoryError (or any other exception/error)

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.12.1
    • Fix Version/s: 2.13.0
    • Component/s: Core
    • Labels:

      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:

      event.execute(endOfBatch);
      event.clear();

      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:

      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% 
      ................

      Also please see RingBufferLogEvent_OOM.log log file with OOM stacktrace:

      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) 

      Could you please fix it or explain if such behavior is expected?

      Thanks,
      Dzmitry

        Attachments

        1. domitator_tree_report_clear_called.txt
          4 kB
          Dzmitry Anikechanka
        2. domitator_tree_report_clear_not_called.txt
          4 kB
          Dzmitry Anikechanka
        3. image-2019-11-27-11-38-50-296.png
          46 kB
          Dzmitry Anikechanka
        4. image-2019-11-27-11-39-49-904.png
          52 kB
          Dzmitry Anikechanka
        5. RingBufferLogEvent_dominator_tree.txt
          4 kB
          Dzmitry Anikechanka
        6. RingBufferLogEvent_OOM.log
          3 kB
          Dzmitry Anikechanka

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                anikosss Dzmitry Anikechanka
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 1h 10m
                  1h 10m