异步日志：性能优化的金钥匙-阿里云开发者社区

一、背景

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

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

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

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

二、原理

2.1 Log4j2的优势

性能: Log4j2使用基于Lambda的异步记录器，显著提高了日志记录的速度，减少了日志操作对应用性能的影响。相比之下，Logback虽然也支持异步记录，但实现上不如Log4j2高效。通过减少对象创建、高效的字符串处理和池化技术，Log4j2在高并发场景下表现更佳。
配置灵活性: 支持多种配置方式，包括XML、JSON、YAML、properties文件，甚至编程式配置，提供更大的灵活性。动态重新配置能力，允许在不重启应用的情况下修改日志配置。
插件架构: Log4j2采用插件架构，几乎所有组件（如Appenders、Layouts、Filters）都是可插拔的，易于扩展和自定义。内置丰富的插件库，开箱即用，简化集成过程。
内存和资源管理: 更高效的内存管理，减少内存泄漏的风险，尤其是在大量日志输出时。支持垃圾回收友好的设计，比如基于Disrupter的RingBuffer等数据结构减少GC压力。
可靠性: 强大的故障恢复机制，如重试和备用Appenders，确保日志能够被记录下来，即使主要的日志输出目的地不可用。
先进的特性:

支持条件日志记录（Conditionals），可以根据运行时条件决定是否记录日志。
自动重新加载配置文件变化，无需重启应用。
支持JMX监控和管理日志系统状态。

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

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

2.2 Log4j2的结构

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

Logger: 这是开发者直接使用的接口，用于记录不同级别的日志信息（如DEBUG, INFO, ERROR等）。每个Logger都有一个名称，并且支持继承性，形成一个名为Logger Hierarchy的树状结构，根Logger的名称为"root"。
LoggerContext: 是日志系统的上下文环境，管理着一组Logger实例以及它们的配置。每个应用程序通常只有一个LoggerContext，但它支持多个上下文以实现更细粒度的控制。
Configuration: 每个LoggerContext都关联一个有效的Configuration，定义了日志的输出目的地（Appenders）、日志的过滤规则（Filters）、日志的格式化方式（Layouts）等。Configuration可以通过配置文件（如XML、JSON、properties）或编程方式动态加载。
Appender: 负责将日志事件发送到指定的目标，如控制台（Console）、文件（File）、数据库、网络Socket等。
Layout: 定义了日志信息的格式化方式，如模式字符串（Pattern String）决定了日期、时间、日志级别、线程名、日志信息等内容的排列和格式。
Filter: 可以在日志事件从Logger传递到Appender的过程中进行过滤，根据特定条件决定日志是否被输出。
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: 锁等待策略。该策略当正在写入日志时，则会等待；否则即会停止等待。

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

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的异步日志

2.5.1 异步日志原理概述

前面提到了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_disruptorDisrupter组件构成：

Disrupter性能测试结果

2.5.2 如何使用异步日志

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

全局异步日志

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


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

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

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

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

混合异步日志
在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>

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

潜在问题：

日志丢失问题：如果机器发生意外重启、发布、掉电导致的jvm进程停止，停留在队列的未来得及输出到目的地的LogEvent可能会丢失
日志顺序问题：由于日志事件是在不同的线程中异步处理的，因此日志条目可能不会严格按照它们产生的顺序出现在日志文件中，这对于需要严格按时间顺序追踪日志的应用可能是个问题。
其他问题：如增加资源损耗、配置复杂度和调试复杂度等问题

解决方案：

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未及时清理对象，容易导致内存泄漏，异步日志场景请慎用。

对于日志顺序性问题：

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

三、效果

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

应用rpc耗时：

应用网关耗时：

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

GC优化后：

四、建议

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

动静分离：在一些大日志输出场景中，即使是异步日志也会给系统带来性能风险。因此建议合理识别大日志中的动态数据和静态数据。静态数据定时输出，动态数据关联唯一静态标识输出，在降低性能风险的同时又满足监控分析的需要；
合理分割：日志文件需要合理分割，并设置合理的保留策略，及时释放磁盘空间。
合理设置日志级别：避免日志滥用，尤其是debug日志，既有利于日志定位问题的速度，又能提高性能。

五、总结

本文主要介绍了Log4j2框架的核心原理、实践应用以及一些实用的小Tips，力图揭示Log4j2这一强大日志记录工具在现代分布式服务架构运维中的关键作用。

来源 | 阿里云开发者公众号
作者 | 柏淳

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

一、背景

二、原理

2.1 Log4j2的优势

2.2 Log4j2的结构

2.3 Log4j2日志输出流程

2.4 如何实现日志脱敏

2.5 Log4j2的异步日志

2.5.1 异步日志原理概述

2.5.2 如何使用异步日志

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

三、效果

四、建议

五、总结

热门文章

最新文章

相关课程

相关电子书

相关实验场景

热门

活动广场

任务中心

开发者评测

高校计划

乘风者计划

训练营

阿里云MVP

话题

直播

下载

镜像站

技术资料

插件

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

一、 背景

二、原理

2.1 Log4j2的优势

2.2 Log4j2的结构

2.3 Log4j2日志输出流程

2.4 如何实现日志脱敏

2.5 Log4j2的异步日志

2.5.1 异步日志原理概述

2.5.2 如何使用异步日志

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

三、效果

四、建议

五、总结

热门文章

最新文章

相关课程

相关电子书

相关实验场景

一、背景