[
https://issues.apache.org/jira/browse/LOG4J2-471?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13855135#comment-13855135
]
Anthony Baldocchi commented on LOG4J2-471:
------------------------------------------
Remko, in my current use case, the RingBuffer is configured to a smaller number
of entries than the default (variable based on heap size and assuming a
near-worst-case referenced object because asynchronous logging can potentially
alter the expected lifecycle of objects if the logging thread is running
behind; I was hitting OutOfMemoryErrors due to some large objects that couldn't
be garbage collected until logging finished but new large objects could be
generated because the thread that issued the log request was not blocked;
262144 large objects overflowed the heap).
However, I think RingBuffer size only impacts the likelihood of encountering
the issue (as the likelihood of hitting a full buffer decreases); as long as
the buffer is filling more quickly than it is being emptied (not difficult to
do with asynchronous logging), the buffer can reach fullness and, once full,
this issue becomes significant. With a high logging rate, a single rollover
event might be all that is needed to reach buffer fullness, no matter how large.
The workaround I'm currently considering is a filter, akin to the BurstFilter,
that makes use of the RingBufferAdmin introduced in 2.0-rc1 to reject logging
events when the RingBuffer is full. I like the idea of the errorAppender you
mention for AsyncAppender; I'm going to see if I can add similar fallback
functionality as I'd like to avoid dropping logging events entirely if at all
possible.
An alternative solution I was considering was making use of a ThreadLocal to
identify the AsyncLogger thread and then since I could determine if the thread
was the AsyncLogger thread and that the RingBuffer was full, skip the publish
event step and instead just call config.loggerconfig.log(...), passing the
arguments on through. Patch for this second solution is attached.
> toString methods that perform logging can deadlock AsyncLogger
> --------------------------------------------------------------
>
> Key: LOG4J2-471
> URL: https://issues.apache.org/jira/browse/LOG4J2-471
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0-beta9
> Environment: Debian Squeeze
> Java 7u25
> Reporter: Anthony Baldocchi
> Assignee: Remko Popma
>
> The AsyncLogger thread is the only consumer of a Disruptor RingBuffer which
> contains log events ostensibly produced by a number of other threads.
> However, when AsyncLogger generates a log message, it has to call toString()
> on objects which can potentially also perform logging internally. This
> results in a situation when the RingBuffer is nearly full whereby AsyncLogger
> has pulled an event from the RingBuffer, calls toString() on the associated
> objects, which call AsyncLogger.log which attempts to publish an event into a
> full buffer, which will park repeatedly without hope of ever leaving the
> loop. Relevant stack trace is:
> "AsyncLogger-1" daemon prio=10 tid=0x00007f7a705a8000 nid=0x3d73 runnable
> [0x00007f7a740d1000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> at
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
> at
> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:133)
> at
> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:102)
> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:391)
> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:219)
> at
> org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:214)
> at
> org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
> at org.slf4j.impl.SLF4JLogger.debug(SLF4JLogger.java:138)
> at org.somepackage.SomeException.toString (SomeException.java:32)
> at java.lang.String.valueOf(String.java:2854)
> at java.io.PrintWriter.println(PrintWriter.java:754)
> at java.lang.Throwable$WrappedPrintWriter.println(Throwable.java:763)
> at java.lang.Throwable.printStackTrace(Throwable.java:654)
> - locked <0x00000000cb2f6380> (a java.io.PrintWriter)
> at java.lang.Throwable.printStackTrace(Throwable.java:720)
> at
> org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.formatOption(ThrowablePatternConverter.java:138)
> at
> org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:80)
> at
> org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:69)
> at
> org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
> at
> org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:167)
> at
> org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:52)
> at
> org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:45)
> at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:111)
> at
> org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
> at
> org.apache.logging.log4j.core.Logger$PrivateConfig.logEvent(Logger.java:273)
> at
> org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:230)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:98)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
> at
> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
