timeout - Dropwizard logback 异步日志轮换导致应用程序线程等待

Question

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

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，则此条件永远不会评估为真，这意味着 async-appender线程将尝试推送到已经满的阻塞队列，因此，将停放自身并等待它，导致应用程序线程也等待。

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

保留所有事件而不丢弃的另一种选择是增加队列大小，使其在文件轮换时尽可能多地增加队列中队列元素的大小。在这种情况下，async-appender线程不会在阻塞队列上等待。

所以我的发现是 logback AsyncAppender如果消息传入速率超过队列消耗速率并且丢弃速率为 0，则 NOT so Async。