logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Anthony Baldocchi (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-471) toString methods that perform logging can deadlock AsyncLogger
Date Sun, 22 Dec 2013 09:42:50 GMT

    [ 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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message