Logback永远挂起

Question

我正在编写一个Java应用程序来路由大量并发消息。该应用程序使用Logback框架进行日志记录，我看到应用程序挂起的令人惊讶的行为。在堆栈跟踪中，我可以看到应用程序线程卡在日志记录调用中：

"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)

似乎阻止了日志调用，试图在<0x00007f089c4a7e88>中使用的java.util.concurrent.ArrayBlockingQueue实例中获取锁定AsyncAppenderBase。

在堆栈跟踪中，我可以看到锁<0x00007f089c4a7e88>由空闲的线程池中的另一个线程持有：

"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)

它看起来像ArrayBlockingQueue的内部锁由该线程持有，随后没有被释放。

这里发生了什么？ java.util.concurrent.ArrayBlockingQueue的竞争条件？ Logback中的一个错误？

我使用的是Java 8u40和Logback 1.2.1。

Answer 1

你可以使用discardingThreshold'当阻塞队列剩余20％的容量时，它将丢弃TRACE，DEBUG和INFO级别的事件，只保留级别WARN和ERROR的事件'

样品

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