异步日志：性能优化的金钥匙

这是2024年的第48篇文章

（ 本文阅读时间：15分钟 ）

01

背景

2024年4月的一个宁静的夜晚，正当大家忙完一天的工作准备休息时，应急群里“咚咚咚”开始报警，提示我们余利宝业务的赎回接口成功率下降。

通过Monitor监控发现，该接口的耗时已经超过了网关配置的超时阈值(2s)，我们临时调整超时阈值止血后，就在排查问题的根因。具体排查过程不是我这篇文章的重点，故忽略，但最终我们发现最近上线新加的相邻两行的日志中，时间相差近1.5s，难道这就是问题的根源吗？

后来，我们去掉了这两行日志后紧急发布，事实证明我们的思路是对的。**紧急发布后，该接口的耗时由之前的2s左右，优化到了600ms左右。后来我们分析发现：该接口在打印日志时，由于要实现日志脱敏，故在Logger.info入口处实现了脱敏功能，但是大日志脱敏比较耗时，从而导致该接口的同步调用耗时激增到1.5s左右（后面我们会说如何解决这个问题）。我的天呐，一行日志竟是性能优化的金钥匙！！！**🤣

但这里有一个问题，我们是去掉了日志的打印，侵入了业务，同时该应用还是用的log4j的日志框架，log4j原生框架是不支持日志异步化的，因此要从根本上业务无侵入的解决因日志而导致的性能问题，需要熟悉log4j2的框架原理。

02

原理

2.1 Log4j2的优势

1）性能: Log4j2使用基于Lambda的异步记录器，显著提高了日志记录的速度，减少了日志操作对应用性能的影响。相比之下，Logback虽然也支持异步记录，但实现上不如Log4j2高效。通过减少对象创建、高效的字符串处理和池化技术，Log4j2在高并发场景下表现更佳。

2）配置灵活性: 支持多种配置方式，包括XML、JSON、YAML、properties文件，甚至编程式配置，提供更大的灵活性。动态重新配置能力，允许在不重启应用的情况下修改日志配置。

3）插件架构: Log4j2采用插件架构，几乎所有组件（如Appenders、Layouts、Filters）都是可插拔的，易于扩展和自定义。内置丰富的插件库，开箱即用，简化集成过程。

4）内存和资源管理: 更高效的内存管理，减少内存泄漏的风险，尤其是在大量日志输出时。支持垃圾回收友好的设计，比如基于Disrupter的RingBuffer等数据结构减少GC压力。

5）可靠性: 强大的故障恢复机制，如重试和备用Appenders，确保日志能够被记录下来，即使主要的日志输出目的地不可用。

6）先进的特性:

• 支持条件日志记录（Conditionals），可以根据运行时条件决定是否记录日志。

• 自动重新加载配置文件变化，无需重启应用。

• 支持JMX监控和管理日志系统状态。

**7）与SLF4J的集成:**虽然这不是特有优势，但Log4j2提供了与SLF4J（Simple Logging Facade for Java）的良好集成，使得从其他日志框架迁移更加平滑。

总的来说，Log4j2的设计更现代化，强调高性能、易用性和灵活性，特别是在大规模分布式系统和高性能应用中表现突出。而Logback和Log4j 1.x虽有各自的优点，但在这些方面逐渐显得力不从心。至于Java Util Logging (JUL)，它是Java标准库的一部分，但功能相对基础，配置和扩展性不如Log4j2和Logback灵活。

2.2 Log4j2的结构

Log4j2的结构主要包括以下几个核心组件：

1）Logger: 这是开发者直接使用的接口，用于记录不同级别的日志信息（如DEBUG, INFO, ERROR等）。每个Logger都有一个名称，并且支持继承性，形成一个名为Logger Hierarchy的树状结构，根Logger的名称为'root'。

2）LoggerContext: 是日志系统的上下文环境，管理着一组Logger实例以及它们的配置。每个应用程序通常只有一个LoggerContext，但它支持多个上下文以实现更细粒度的控制。

3）Configuration: 每个LoggerContext都关联一个有效的Configuration，定义了日志的输出目的地（Appenders）、日志的过滤规则（Filters）、日志的格式化方式（Layouts）等。Configuration可以通过配置文件（如XML、JSON、properties）或编程方式动态加载。

4）Appender: 负责将日志事件发送到指定的目标，如控制台（Console）、文件（File）、数据库、网络Socket等。

5）Layout: 定义了日志信息的格式化方式，如模式字符串（Pattern String）决定了日期、时间、日志级别、线程名、日志信息等内容的排列和格式。

6）Filter: 可以在日志事件从Logger传递到Appender的过程中进行过滤，根据特定条件决定日志是否被输出。

7）Lookup: 提供动态值解析机制，如${ctx:variable}可以在日志中插入上下文变量的值。

那么，Log4j2的日志是怎么将日志输出到文件/数据库/控制台等地方的？

2.3 Log4j2日志输出流程

关键步骤源码分析：

1）1.1主要是针对日志级别Level和指定的全局Filter组件进行过滤

2）ReliabilityStrategy是Log4j2的日志可靠性策略实现，目前主要有以下四种：

• AwaitCompletionReliabilityStrategy: 等待日志接收完成策略。这种策略主要是在应用关闭时，尽可能要等应用日志接收完成后再结束Appender的生命周期（这种策略只是说尽可能所有日志等待调用Appender.append方法完成，但在异步日志场景下，Appender.append其实是落了ringbuffer或者其他队列里，实际上未持久化。因此该策略是尽可能保证接收完成而非处理完成）

• AwaitUnconditionallyReliabilityStrategy: 无条件等待策略。这种策略会在rootLogger关闭时无条件等待一段时间，具体等待时间可以配置log4j2.component.properties文件的log4j.waitMillisBeforeStopOldConfig属性。

• DefaultReliabilityStrategy: 默认策略。该策略不做任何等待。

• LockingReliabilityStrategy: 锁等待策略。该策略当正在写入日志时，则会等待；否则即会停止等待。

3）1.2.1.3.1append操作是将日志写入到对应的目的地，如kafka、本地文件、邮件等。这里如果是异步日志，则会将日志追加到异步队列里，进而提高日志记录的性能。

4）1.2.1.3.1.1调用Layout encode日志，是根据log4j2.xml中配置的Layout对日志进行格式化输出。

那么如果有一些个性化的日志输出需求，log4j2能否帮我们实现？

2.4 如何实现日志脱敏

上面提到了log4j2的各种组件以及日志输出流程，log4j2的强大很大程度上得益于其清晰且高度解耦的架构设计。例如其具有很强的扩展性，log4j2的很多组件都可以自己定制插件，如：Appender、Filter、Layout等。那么这里我结合我们实际业务中一个很常见的case去分析如何定制一个组件。

首先，**作为一家强监管的金融公司，日志脱敏涉及数据保护和隐私安全等问题，非常重要。**过去我们很多业务系统在实现业务脱敏时，很容易想到在打日志的入口统一封装一个格式化方法，造成日志输出在无形中把异步日志输出变成了同步输出（日志脱敏的耗时往往比日志集中持久化到磁盘耗时要高）。

那么如何优雅的实现日志脱敏的功能，既能实现其功能又可以保证日志的性能，是log4j2插件化的一个很重要的应用场景。前面我们提到日志输出流程中会使用Layout encode日志，而PatternConverter是Layout非常重要的组成部分。其通过定义一系列的占位符（如%d、%m、 %t等）帮助我们自定义格式输出日志对象，同时PatternConverter支持以高度可定制的插件集成到Log4j2框架中，因此我们可以借助其去定制脱敏组件。

话不多说，我们直接上日志脱敏PatternConverter插件源码：

`//``// Source code recreated from a .class file by IntelliJ IDEA``// (powered by FernFlower decompiler)``//``import java.util.Arrays;``   ``import org.apache.logging.log4j.core.LogEvent;``import org.apache.logging.log4j.core.config.plugins.Plugin;``import org.apache.logging.log4j.core.pattern.ConverterKeys;``import org.apache.logging.log4j.core.pattern.LogEventPatternConverter;``import org.apache.logging.log4j.message.FormattedMessage;``import org.apache.logging.log4j.message.Message;``import org.apache.logging.log4j.message.MessageFormatMessage;``import org.apache.logging.log4j.message.ParameterizedMessage;``import org.apache.logging.log4j.message.StringFormattedMessage;``import org.apache.logging.log4j.util.PerformanceSensitive;``   ``/**` `* @author baichun` `* @version ShieldMessagePatternConverter.java, v 0.1 2024年04月09日 21:13 baichun` `*/``@Plugin(`        `name = "ShieldPatternConverter",`        `category = "Converter"``)``@ConverterKeys({"shield", "sd", "shieldMessage", "sm"})``@PerformanceSensitive({"allocation"})``public final class ShieldMessagePatternConverter extends LogEventPatternConverter {`    `private final String[] options;``   `    `private ShieldMessagePatternConverter(String[] options) {`        `super("Shield", "shield");`        `this.options = options == null ? null : (String[])Arrays.copyOf(options, options.length);`    `}``   `    `//必须要有newInstance方法，log4j2会调用该方法进行初始化`    `public static ShieldMessagePatternConverter newInstance(String[] options) {`        `return new ShieldMessagePatternConverter(options);`    `}``   ``   `    `@Override`    `public void format(LogEvent logEvent, StringBuilder output) {`        `Message message = logEvent.getMessage();`        `String format = message.getFormat();``   `        `if (isFormatMessage(message)) {`            `//在这里格式化脱敏日志`            `String msgInfo = ShieldUtils.format(format, message.getParameters());``   `            `output.append(msgInfo);`        `} else {`            `output.append(message.getFormattedMessage());`        `}`    `}``   `    `private boolean isFormatMessage(Message message) {`        `return message instanceof ParameterizedMessage || message instanceof StringFormattedMessage`                `|| message instanceof FormattedMessage || message instanceof MessageFormatMessage;`    `}``}`

定义好组件后，log4j2即能够自动扫描识别到，不需要其他定义和配置。接下来看看如何使用。ConverterKeys这个注解指定了在log4j2.xml中应如何使用该插件。以下是log4j2.xml应用示例：

        `<RollingFile name="TEST_APPENDER" fileName="test.log"`                     `filePattern="test.log.%d{yyyy-MM-dd}"`                     `append="true">`            `<!-- %sm即为脱敏组件 -->`            `<PatternLayout pattern="%d %sm%n" charset="UTF-8"/>`            `<TimeBasedTriggeringPolicy/>`            `<DefaultRolloverStrategy/>`        `</RollingFile>`

2.5 Log4j2的异步日志

异步日志原理概述

前面提到了Log4j2的高可扩展性，同时Log4j2的性能也是极高的，下面是Log4j2官方的benchmark数据，仅供参考：

Log4j2之所以性能如此之高，其中一个很重要的原因就是其基于Disrupter的环形缓冲区的无锁化结构Ringbuffer设计。Disruptor是英国外汇交易公司LMAX开发的一个高性能队列，基于Disruptor开发的系统单线程能支撑每秒600万订单。目前，包括Apache Strom、Log4j2在内的很多知名项目都应用了Disruptor来获取高性能。关于Disruptor的原理，这里不再赘述，大家可以自行查阅：https://lmax-exchange.github.io/disruptor/#\_what\_is\_the\_disruptor

Disrupter组件构成：

Disrupter性能测试结果

如何使用异步日志

log4j2开启异步日志的方法主要有以下两种方式：

1）全局异步日志

• 通过JVM启动参数来全局启用异步日志功能。在启动应用程序时，向JVM传递以下系统属性：

 `-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector`

• 在类路径（classpath）中添加一个名为log4j2.component.properties的文件，并包含以下内容（这个文件会在Log4j2初始化时被读取）：

Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

  

这两种方式下，所有Logger都会自动使用异步处理。

  

2）混合异步日志
在log4j2.xml配置文件中，可以手动指定特定的Logger使用异步处理，通过将 或元素替换为或。例如：

<Configuration status='WARN'>``<Appenders> ... <!-- your appenders here -->``</Appenders>``<Loggers>``<AsyncRoot level='info' includeLocation='false'>``<AppenderRef ref='yourAppenderName'/>``</AsyncRoot>``<!-- 或者为特定logger配置 -->``<AsyncLogger name='com.example.MyClass' level='debug'>``<AppenderRef ref='yourAppenderName'/>``</AsyncLogger>``</Loggers>``</Configuration>

异步日志的潜在问题及解决方案

• 潜在问题：

1. **日志丢失问题：**如果机器发生意外重启、发布、掉电导致的jvm进程停止，停留在队列的未来得及输出到目的地的LogEvent可能会丢失

2. **日志顺序问题：**由于日志事件是在不同的线程中异步处理的，因此日志条目可能不会严格按照它们产生的顺序出现在日志文件中，这对于需要严格按时间顺序追踪日志的应用可能是个问题。

3. 其他问题：如增加资源损耗、配置复杂度和调试复杂度等问题

• 解决方案：

1. 对于日志丢失问题：

• 原生Log4j2有完整的生命周期管理，并监听了jvm关闭的事件。当jvm关闭时，Log4j2会监听Disrupter队列中的RingbufferLogEvent数量，直到日志打印完（或超时）才释放关闭Log4j2，jvm才得以正常关闭。但是自然灾害或者机房掉电等不可抗力因素，无法避免丢失问题。

• **我们基于Log4j2定制的AsyncAbleRollingFileAppender，其中有独立的Disrupter，且不在Log4j2生命周期管理当中，存在日志丢失风险。**可以采用类似方案解决：

try { LoggerContextFactory factory = LogManager.getFactory(); if (!(factory instanceof Log4jContextFactory)) { return; } Log4jContextFactory log4jContextFactory = (Log4jContextFactory) factory; ShutdownCallbackRegistry registry = log4jContextFactory.getShutdownCallbackRegistry(); if (!(registry instanceof DefaultShutdownCallbackRegistry)) { return; } DefaultShutdownCallbackRegistry defaultShutdownCallbackRegistry = (DefaultShutdownCallbackRegistry) registry; Field hooksField = DefaultShutdownCallbackRegistry.class.getDeclaredField("hooks"); hooksField.setAccessible(true); Collection<Cancellable> hooks = (Collection<Cancellable>) hooksField.get(defaultShutdownCallbackRegistry); Collection<Cancellable> newHooks = new CopyOnWriteArrayList<>(); //将对Appender的队列消费监听和卸载放在首要位置，避免log4j2关闭后再卸载Appender newHooks.add(new Log4j2Cancellable(() -> { //负责监听AsyncAbleRollingFileAppender的队列消费情况，并在消费完成后关闭AsyncAbleRollingFileAppender new AppenderUnInstaller(register).run(); })); newHooks.addAll(hooks); hooksField.set(defaultShutdownCallbackRegistry, newHooks); } catch (NoSuchFieldException e) { // This catch statement is intentionally empty } catch (IllegalAccessException e) { // This catch statement is intentionally empty }

• AsyncAbleRollingFileAppender使用独立的disrupter，且RingBufferLogEvent未及时清理对象，容易导致内存泄漏，异步日志场景请慎用。

2. 对于日志顺序性问题：

• 异步线程池大小设置为1，但是会影响日志打印的速度（现在的普遍做法）。

• 延迟打印

03

效果

4月份的这一问题发生后，我们从原理出发，对理财的核心应用做了升级和优化，整体服务耗时上取得了不错的性能优化效果。

应用rpc耗时：

应用网关耗时：

但与此同时，我们也发现升级后，应用的fgc次数更多了，经过heapdump分析后，发现AsyncAbleRollingFileAppender内部实现的RingBufferLogEvent执行后，不会释放引用的LogEvent，导致Disrupter一直持有已打印的LogEvent的引用关系，进而导致了内存泄漏。后来，我们采取主动释放对象引用（RingBufferLogEvent.setLogEvent(null)）优化的方案，发布以后前后fgc对比如下：

GC优化前：

GC优化后：

04

建议

日志作为诊断问题、监控系统健康状况与优化服务效能不可或缺的一环，其重要性不言而喻。熟练掌握并有效利用如Log4j2这样的高性能日志框架以及注意一些打印日志的策略（如动静分离、合理分割、合理设置日志级别等），对于开发者而言至关重要：

1）动静分离 ：在一些大日志输出场景中，即使是异步日志也会给系统带来性能风险。因此建议合理识别大日志中的动态数据和静态数据。静态数据定时输出，动态数据关联唯一静态标识输出，在降低性能风险的同时又满足监控分析的需要；

2）合理分割 ：日志文件需要合理分割，并设置合理的保留策略，及时释放磁盘空间。

3）合理设置日志级别 ：避免日志滥用，尤其是debug日志，既有利于日志定位问题的速度，又能提高性能。

欢迎留言一起参与讨论~