Logback hängt für immer

Question

Ich schreibe eine Java-Anwendung, um eine hohe Anzahl gleichzeitiger Nachrichten zu routen. Die Anwendung verwendet das Logback-Framework für die Protokollierung und ich sehe ein überraschendes Verhalten, bei dem die Anwendung hängt. In einer Stack-Trace kann ich, dass Anwendungsfäden steckt in Protokollierung Anrufen sehen:

"New I/O client worker #1-1" #125 prio=5 os_prio=0 tid=0x00007f0524017000 nid=0x29f3 waiting on condition [0x00007f052ecea000] 
    java.lang.Thread.State: WAITING (parking) 
     at sun.misc.Unsafe.park(Native Method) 
     - parking to wait for <0x00007f089c4a7e88> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) 
     at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) 
     at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) 
     at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) 
     at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) 
     at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) 
     at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) 
     at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(ArrayBlockingQueue.java:468) 
     at ch.qos.logback.core.AsyncAppenderBase.isQueueBelowDiscardingThreshold(AsyncAppenderBase.java:152) 
     at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:144) 
     at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) 
     at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) 
     at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) 
     at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) 
     at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) 
     at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) 
     at ch.qos.logback.classic.Logger.info(Logger.java:579) 
     at com.application.ClientListener$6.operationComplete(***.java:514) 
     - locked <0x00007f089c372b60> (a com.application.ClientListener) 
     at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:381) 
     at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:372) 
     at org.jboss.netty.channel.DefaultChannelFuture.setSuccess(DefaultChannelFuture.java:316) 
     at org.jboss.netty.channel.socket.nio.NioWorker$RegisterTask.run(NioWorker.java:776) 
     at org.jboss.netty.channel.socket.nio.NioWorker.processRegisterTaskQueue(NioWorker.java:257) 
     at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:199) 
     at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) 
     at org.jboss.netty.util.internal.IoWorkerRunnable.run(IoWorkerRunnable.java:46) 
     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) 

    Locked ownable synchronizers: 
     - <0x00007f08a80fc118> (a java.util.concurrent.ThreadPoolExecutor$Worker) 

Es scheint, dass der Protokollierung-Aufruf ein Schloss <0x00007f089c4a7e88> in einer java.util.concurrent.ArrayBlockingQueue Instanz in AsyncAppenderBase verwendet zu erwerben blocked versucht.

Im Stack-Trace, kann ich sehen, dass das Schloss <0x00007f089c4a7e88> von einem anderen Thread in einem Thread-Pool gehalten wird, der im Ruhezustand befindet:

"dispatcher-3" #90 prio=5 os_prio=0 tid=0x00007f04d0004800 nid=0x29d2 waiting on condition [0x00007f0534ed3000] 
    java.lang.Thread.State: WAITING (parking) 
     at sun.misc.Unsafe.park(Native Method) 
     - parking to wait for <0x00007f089cbbaae8> (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 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081) 
     at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) 
     at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) 
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) 
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) 
     at java.lang.Thread.run(Thread.java:745) 

    Locked ownable synchronizers: 
     - <0x00007f089c4a7e88> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) 

Es sieht aus wie die interne Sperre der ArrayBlockingQueue von diesem Thread gehalten wurde und anschließend nicht freigegeben.

Was geht hier vor? Eine Wettlaufbedingung in java.util.concurrent.ArrayBlockingQueue? Ein Fehler in Logback?

Ich verwende Java 8u40 und Logback 1.2.1.

Answer 1

können Sie discardingThreshold verwenden ‚wenn die Sperr Warteschlange 20% Restkapazität hat, es Ereignisse Ebene TRACE, DEBUG und INFO fallen wird, nur Ereignisse Niveau zu halten WARN und ERROR‘

Probe

<appender name="ASYNCFile" class="ch.qos.logback.classic.AsyncAppender"> 
     <queueSize>50</queueSize> 
     <discardingThreshold>2</discardingThreshold> 
     <appender-ref ref="fileAppender" /> 
    </appender>