Log4j2 in async mode still blocks on java.util.concurrent.lock under heavy load

Question

I am trying to log in a low-latency environment.
2 high priority threads are calling log.error() in a tight loop (1Mmessages/s)

I want to use Async logging (with the disruptor) and to discard any excess messages. So the calling thread should NEVER block.

However, the jstack clearly shows it is blocking about 100 times/s.

Is it my configuration which is wrong ? Or is the blocking inevitable if the buffer fill up ?

java -Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-Dlog4j2.AsyncQueueFullPolicy=Discard
-Dlog4j2.DiscardThreshold=Trace
-DAsyncLogger.RingBufferSize=2000000 TestLog


"TT0" #14 prio=5 os_prio=0 tid=0x00007fe8cc690800 nid=0x2463 runnable [0x00007fe8ae70d000]
   java.lang.Thread.State: RUNNABLE
        at sun.misc.Unsafe.unpark(Native Method)
        at java.util.concurrent.locks.LockSupport.unpark(LockSupport.java:141)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.unparkSuccessor(AbstractQueuedSynchronizer.java:662)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1264)
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457)
        at com.lmax.disruptor.BlockingWaitStrategy.signalAllWhenBlocking(BlockingWaitStrategy.java:72)
        at com.lmax.disruptor.MultiProducerSequencer.publish(MultiProducerSequencer.java:218)
        at com.lmax.disruptor.RingBuffer.translateAndPublish(RingBuffer.java:934)
        at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:444)
        at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:245)
        at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:285)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:727)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:716)
        at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:232)
        at TestLog$WriteToFile.run(TestLog.java:53)
        at java.lang.Thread.run(Thread.java:745)

"AsyncLogger-1" #12 daemon prio=5 os_prio=0 tid=0x00007fe8cc96f800 nid=0x2460 waiting on condition [0x00007fe8b4187000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007104a0f28> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
        at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
        at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
        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)

I am showing the stack trace of 1 writer and the log4j2 thread — user7564034
– user7564034, Commented Feb 14, 2017 at 16:35

Remko Popma · Accepted Answer · 2017-02-14 22:29:58Z

2

The LMAX Disruptor allows you to choose what the background thread should do when it's waiting for work to arrive.

By default Log4j2 uses the BlockingWaitStrategy. This gives the behavior you are seeing, which is appropriate for most situations but perhaps not in ultra low latency use cases.

If you can dedicate a core to the background thread you can use the BusySpin wait strategy.

See https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java

edited Feb 14, 2017 at 22:29

answered Feb 14, 2017 at 22:17

Remko Popma

37.2k11 gold badges98 silver badges122 bronze badges

Sign up to request clarification or add additional context in comments.

3 Comments

user7564034 Over a year ago

I am concerned about the "TT0" which is the main application thread. It appears to be accesing a SYNCHONIZE data structure, which i find suprising. If every time i do a jstack i see it, then i guess it is spending a lot of time there.

Remko Popma Over a year ago

Yes this will also go away if you use the BusyWait strategy. Currently the application thread needs to take a lock to notify the background thread that it should wake up because work has arrived.

user7564034 Over a year ago

Great. This makes sense.

Collectives™ on Stack Overflow

Log4j2 in async mode still blocks on java.util.concurrent.lock under heavy load

1 Answer 1

3 Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

3 Comments

Your Answer

Sign up or log in

Post as a guest

Related