One other thing. My expectation is that once the buffer is full you should continue to log but at the rate your underlying system can handle. This wouldn’t be a deadlock but if the rate at which you are logging is higher than the system can write the result will be that the application slows down.
If you are truly seeing a deadlock then it is possible there is a problem in the disruptor but I have very little experience with that and would need Remko to weigh in. Ralph > On Mar 14, 2021, at 12:26 AM, Ralph Goers <ralph.go...@dslextreme.com> wrote: > > Yes, it rings bells and really should have a slot on our FAQ page (although > the question really isn’t asked all that frequently). > > First it means that you are logging faster than your system can handle. The > proper response is to figure out why you are logging so much and try to > reduce it or use an alternative destination that is faster. For example, if > you are logging to a file you may need to improve the hardware or increase > the buffer size. > > As you observed your buffer has filled up. The default behavior is for > threads to wait until there is an empty slot. > > Remko is the real expert on this but I will take a stab at answering your > question. The threads below show that they are in handleRingBufferFull. That > method has 3 options to choose from based on how you have configured the > asyncQueueFullPolicy. You basically have 3 choices: > Wait for an open slot (the default) > Resort to logging synchronously. > Discard log events. > > You should look at > https://logging.apache.org/log4j/2.x/log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html > > <https://logging.apache.org/log4j/2.x/log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html>. > Note that option 2 above (synchronous) is only used by Log4j in certain > circumstances and there isn’t an option to specify that, so the only real > options are the default behavior, discarding, or create a custom > AsyncQueueFullPolicy. > > Ralph > > > >> On Mar 13, 2021, at 10:32 PM, Leon Finker <leon...@gmail.com> wrote: >> >> HI, >> >> Using log4j2 1.13.1 with disruptor 3.4.2. Linux CentOS. JRE 11.0.5 >> Using the following JRE args: >> -DAsyncLogger.RingBufferSize=32768 >> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector >> -Dlog4j.configurationFile=... >> >> The disruptor queue has filled up. And we've observed deadlock with >> the interesting threads stuck like the following. Disruptor processing >> thread seems to be waiting to process events and all the other threads >> locked up on trying to publish the events. >> >> "Log4j2-TF-1-AsyncLogger[AsyncContext@5cb0d902]-1" #23 daemon prio=5 >> os_prio=0 cpu=40099128.73ms elapsed=44102.95s tid=0x00007f4c2ca34000 >> nid=0x611a runnable [0x00007f4bfdcfc000] >> java.lang.Thread.State: RUNNABLE >> at >> com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56) >> at >> com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:159) >> at >> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125) >> at java.lang.Thread.run(java.base@11.0.5/Thread.java:834) >> >> Locked ownable synchronizers: >> - None >> >> >> "xxx" #268 prio=5 os_prio=0 cpu=7051742.32ms elapsed=43967.04s >> tid=0x00007f4c2e6ea800 nid=0x649d runnable [0x00007f49f77dd000] >> java.lang.Thread.State: TIMED_WAITING (parking) >> at jdk.internal.misc.Unsafe.park(java.base@11.0.5/Native Method) >> at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.5 >> /LockSupport.java:357) >> at >> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136) >> at >> com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105) >> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:465) >> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:331) >> at >> org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull(AsyncLoggerDisruptor.java:230) >> - locked <0x0000000701017288> (a java.lang.Object) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:246) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:230) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:225) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.access$000(AsyncLogger.java:67) >> at >> org.apache.logging.log4j.core.async.AsyncLogger$1.log(AsyncLogger.java:152) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:136) >> at >> org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2198) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2152) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2135) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2016) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1875) >> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179) >> ... >> at java.lang.Thread.run(java.base@11.0.5/Thread.java:834) >> >> Locked ownable synchronizers: >> - None >> >> and all other threads are stuck like this: >> "xx-nioW-16" #273 prio=5 os_prio=0 cpu=7439.15ms elapsed=43966.67s >> tid=0x00007f4c2e4c7000 nid=0x64a9 waiting for monitor entry >> [0x00007f49f6ad2000] >> java.lang.Thread.State: BLOCKED (on object monitor) >> at >> org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull(AsyncLoggerDisruptor.java:230) >> - waiting to lock <0x0000000701017288> (a java.lang.Object) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:246) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:230) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:225) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.access$000(AsyncLogger.java:67) >> at >> org.apache.logging.log4j.core.async.AsyncLogger$1.log(AsyncLogger.java:152) >> at >> org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:136) >> at >> org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2198) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2152) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2135) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2022) >> at >> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1891) >> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:194) >> ... >> >> Does this ring any bells? >> >> Thank you in advance! > --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
