Log4j2 im asynchronen Modus blockiert immer noch auf java.util.concurrent.lock unter hoher Last

Question

Ich versuche, eine Umgebung mit niedriger Latenz einzuloggen.
2 hohe Priorität Threads rufen log.error() in einer engen Schleife (1Mmessages/s)

I asynchrones Logging verwenden möchten (mit dem Disruptor) und überschüssige Nachrichten zu verwerfen. Also sollte der aufrufende Thread NIE blockieren.

Allerdings zeigt der Jstack deutlich, dass es etwa 100 mal/s blockiert.

Ist meine Konfiguration falsch? Oder ist die Blockierung unvermeidlich, wenn der Puffer voll ist?

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) 

Answer 1

Die LMAX Disruptor können Sie wählen, was der Hintergrund-Thread tun sollte, wenn es für die Arbeit wartet ankommen.

Log4j2 verwendet standardmäßig die BlockingWaitStrategy. Dies gibt das Verhalten an, das Sie sehen, das für die meisten Situationen geeignet ist, aber möglicherweise nicht in Anwendungsfällen mit extrem niedriger Latenz.

Wenn Sie dem Hintergrund-Thread einen Core zuweisen können, können Sie die BusySpin-Warte-Strategie verwenden.

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