Logback AsyncAppender间歇性性能问题排查求助

我当前使用Logback AsyncAppender，它大幅降低了日志延迟，但仍间歇性出现高延迟问题。如下两条连续日志显示延迟达488ms，原因不明：

2023-04-24 05:42:05.446 [SofaBizProcessor-5-thread-4]   INFO[06023f5c168234012297211431566]search (rule,keyword) mappings with key: isContainerLink
2023-04-24 05:42:05.934 [SofaBizProcessor-5-thread-4]   WARN[06023f5c168234012297211431566]no (rule,keyword) mapping are present, try to match directly with key: isContainerLink

我的Logback配置如下：

<!-- neverBlock true means possible loss of logging events in case of full queue -->
<appender name="ASYNC_MODULE_APPENDER" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="MODULE_APPENDER" />
    <queueSize>1024</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <neverBlock>true</neverBlock>
</appender>

由于我设置了neverBlock=true，本应完全无延迟/阻塞，请问可能的原因是什么？

可能的原因分析 #

• 日志事件构建的主线程开销：AsyncAppender仅负责把日志事件异步提交到队列，但日志事件的创建、参数格式化、MDC上下文复制等操作都是在主线程执行的。如果日志内容涉及复杂对象序列化、大量字符串拼接，或者MDC存储了大量需要复制的数据，这部分操作会直接消耗主线程时间，导致日志时间戳出现间隔。比如你日志里的traceId如果需要从MDC读取或生成，也可能带来额外开销。
• 队列操作的CAS竞争：即使neverBlock=true，主线程往队列里提交日志时依赖CAS（比较并交换）操作。当业务高并发、大量线程同时写入队列，或者队列使用率较高时，CAS操作的失败重试会导致主线程短暂停顿，反映为日志延迟。
• JVM层面的停顿：GC停顿、JIT编译停顿会导致所有线程（包括主线程）暂停执行，这是间歇性高延迟的常见原因。可以检查对应时间段的GC日志，看是否存在Full GC或长时间的Young GC停顿。
• 后台工作线程的阻塞传导：AsyncAppender的后台线程如果被下游MODULE_APPENDER阻塞（比如写磁盘时遇到IO瓶颈、远程日志服务超时、锁竞争），会导致队列日志堆积。虽然主线程不会被阻塞，但如果队列接近饱和，主线程的入队操作竞争会加剧；另外，后台线程处理滞后也会让日志输出时间晚于实际发生时间，但你看到的是主线程日志时间戳间隔大，所以更偏向主线程自身或JVM停顿问题。
• 队列容量设置不合理：当前queueSize=1024，如果业务高峰期日志量突增，队列快速被占满，neverBlock=true会触发日志丢失，但在队列满之前，高使用率会放大CAS操作的竞争概率，导致主线程短暂延迟。

内容的提问来源于stack exchange，提问作者machinarium