Dropwizard logback异步日志循环导致应用程序线程等待

Question

每当日志文件旋转时，应用程序线程就会卡住，这会导致我使用Async Appender的API的延迟时间加剧，不确定为什么在轮换期间应用程序线程正在等待。

logback.xml

<configuration debug="true">
<property name="async.discardingThreshold" value="0"/>
<property name="async.queueSize" value="500"/>
<property name="log.dir" value="/var/log"/>
<property name="log.pattern" value="%highlight(%-5level) [%date] [%thread] [%X{id}] [%cyan(%logger{0})]: %message%n"/>
<property name="errorLog.pattern" value="%highlight(%-5level) [%date] [%thread] [%X{id}] [%red(%logger{0})]: %message%n"/>
<property name="log.maxHistory" value="200"/>
<property name="log.default.maxFileSize" value="100MB"/>
<property name="log.error.maxFileSize" value="10MB"/>


<appender name="INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.dir}/default.log</File>
    <Append>true</Append>
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <fileNamePattern>${log.dir}/default.%i.log.gz</fileNamePattern>
        <maxIndex>${log.maxHistory}</maxIndex>
    </rollingPolicy>
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>${log.default.maxFileSize}</maxFileSize>
    </triggeringPolicy>
    <encoder>
        <pattern>%replace(${log.pattern}){'"pin":"\d+"','"pin":"XXXX"'}%n</pattern>
    </encoder>
</appender>

<appender name="ASYNC-INFO" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>${async.discardingThreshold}</discardingThreshold>
    <queueSize>${async.queueSize}</queueSize>
    <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
        <OnMismatch>DENY</OnMismatch>
        <OnMatch>NEUTRAL</OnMatch>
    </filter>
    <appender-ref ref="INFO"/>
</appender>

<appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log.dir}/error.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <fileNamePattern>${log.dir}/error.%i.log.gz</fileNamePattern>
        <maxIndex>${log.maxHistory}</maxIndex>
    </rollingPolicy>
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>${log.error.maxFileSize}</maxFileSize>
    </triggeringPolicy>
    <encoder>
        <pattern>%replace(${errorLog.pattern}){'"pin":"\d+"','"pin":"XXXX"'}%n</pattern>
    </encoder>
</appender>

<appender name="ASYNC-ERROR" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>${async.discardingThreshold}</discardingThreshold>
    <queueSize>${async.queueSize}</queueSize>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>ERROR</level>
    </filter>

    <appender-ref ref="ERROR"/>
</appender>


<root level="INFO">
    <appender-ref ref="ASYNC-ERROR"/>
    <appender-ref ref="ASYNC-INFO"/>
</root>

Answer 1

在我们指定的logback.xml中，

<property name="async.discardingThreshold" value="0"/>

现在快速浏览一下源代码，可以看出可能会发生什么，导致轮换时出现延迟

 @Override
  protected void append(E eventObject) {
    if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
      return;
    }
    preprocess(eventObject);
    put(eventObject);
  }
  private boolean isQueueBelowDiscardingThreshold() {
    return (blockingQueue.remainingCapacity() < discardingThreshold);  
  }

blockingQueue.remainingCapacity() < discardingThreshold，如果丢弃阈值是0，这个条件将永远不会评估为true，这意味着async-appender线程将尝试推送到已经完全阻塞队列，因此，将停放并等待它导致应用程序线程等待。

将此值设置为大于0的任何值都不会导致超时，但是，某些事件可能会丢失。

保持所有事件没有丢弃的另一个选择是将队列大小增加到文件轮换时的队列大小，不超过队列中队列元素的大小。在这种情况下，async-appender线程不会在阻塞队列上等待。

因此，如果消息传入速率超过队列消耗速率且丢弃率为0，则我的发现是logback AsyncAppender不是如此异步。