Yes unfortunately, all logging stopped and nothing was seen in the log file for about 2 hrs till service was restarted. But there is nothing pointing to a deadlock in the threads dump we git so far :( However, the threads dump captured was part of our standard kill -3 if the process isn't exiting normally. So it may not show the correct picture during shutdown.
On Sun, Mar 14, 2021 at 3:32 AM Ralph Goers <ralph.go...@dslextreme.com> wrote: > > 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 > --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
