异步日志:性能优化的金钥匙
![异步日志:性能优化的金钥匙](https://static001.geekbang.org/infoq/ff/ff7267a0de043b4d7fa5c68bb907d752.png)
一、背景
2024 年 4 月的一个宁静的夜晚,正当大家忙完一天的工作准备休息时,应急群里“咚咚咚”开始报警,提示我们余利宝业务的赎回接口成功率下降。
通过 Monitor 监控发现,该接口的耗时已经超过了网关配置的超时阈值(2s),我们临时调整超时阈值止血后,就在排查问题的根因。具体排查过程不是我这篇文章的重点,故忽略,但最终我们发现最近上线新加的相邻两行的日志中,时间相差近 1.5s,难道这就是问题的根源吗?
后来,我们去掉了这两行日志后紧急发布,事实证明我们的思路是对的。紧急发布后,该接口的耗时由之前的 2s 左右,优化到了 600ms 左右。后来我们分析发现:该接口在打印日志时,由于要实现日志脱敏,故在 Logger.info 入口处实现了脱敏功能,但是大日志脱敏比较耗时,从而导致该接口的同步调用耗时激增到 1.5s 左右(后面我们会说如何解决这个问题)。我的天呐,一行日志竟是性能优化的金钥匙!!!🤣
![](https://static001.geekbang.org/infoq/6d/6d5d531b021a36ff88edbb274e612e96.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
但这里有一个问题,我们是去掉了日志的打印,侵入了业务,同时该应用还是用的 log4j 的日志框架,log4j 原生框架是不支持日志异步化的,因此要从根本上业务无侵入的解决因日志而导致的性能问题,需要熟悉 log4j2 的框架原理。
二、原理
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 的结构
![](https://static001.geekbang.org/infoq/b7/b74a49bf2e45b9ac5cf0d49375d55b6f.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
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 日志输出流程
![](https://static001.geekbang.org/infoq/19/194af3d2a86746f3eeb159727311db1d.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
关键步骤源码分析:
1)1.1 主要是针对日志级别 Level 和指定的全局 Filter 组件进行过滤
![](https://static001.geekbang.org/infoq/52/527b3f9c34637ab28f8c37ac05919fcd.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
![](https://static001.geekbang.org/infoq/b2/b2cdfe8cf3c493bfe6afedc35e0fff90.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
![](https://static001.geekbang.org/infoq/9b/9be534323458a4fce995998b15245c53.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
2)ReliabilityStrategy 是 Log4j2 的日志可靠性策略实现,目前主要有以下四种:
AwaitCompletionReliabilityStrategy: 等待日志接收完成策略。这种策略主要是在应用关闭时,尽可能要等应用日志接收完成后再结束 Appender 的生命周期(这种策略只是说尽可能所有日志等待调用 Appender.append 方法完成,但在异步日志场景下,Appender.append 其实是落了 ringbuffer 或者其他队列里,实际上未持久化。因此该策略是尽可能保证接收完成而非处理完成)
![](https://static001.geekbang.org/infoq/a9/a9dbf6ae5ac3599f4072bef1044afc70.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
AwaitUnconditionallyReliabilityStrategy: 无条件等待策略。这种策略会在 rootLogger 关闭时无条件等待一段时间,具体等待时间可以配置 log4j2.component.properties 文件的 log4j.waitMillisBeforeStopOldConfig 属性。
![](https://static001.geekbang.org/infoq/d7/d752dcfe907089101b7e52202b5a17c4.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
DefaultReliabilityStrategy: 默认策略。该策略不做任何等待。
LockingReliabilityStrategy: 锁等待策略。该策略当正在写入日志时,则会等待;否则即会停止等待。
![](https://static001.geekbang.org/infoq/93/9373189a9699dd7447d919160d2894be.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
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 插件源码:
定义好组件后,log4j2 即能够自动扫描识别到,不需要其他定义和配置。接下来看看如何使用。ConverterKeys 这个注解指定了在 log4j2.xml 中应如何使用该插件。以下是 log4j2.xml 应用示例:
2.5 Log4j2 的异步日志
异步日志原理概述
前面提到了 Log4j2 的高可扩展性,同时 Log4j2 的性能也是极高的,下面是 Log4j2 官方的 benchmark 数据,仅供参考:
![](https://static001.geekbang.org/infoq/64/64d047bc387b688ae9205996cff35764.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
Log4j2 之所以性能如此之高,其中一个很重要的原因就是其基于 Disrupter 的环形缓冲区的无锁化结构 Ringbuffer 设计。Disruptor 是英国外汇交易公司 LMAX 开发的一个高性能队列,基于 Disruptor 开发的系统单线程能支撑每秒 600 万订单。目前,包括 Apache Strom、Log4j2 在内的很多知名项目都应用了 Disruptor 来获取高性能。关于 Disruptor 的原理,这里不再赘述,大家可以自行查阅:https://lmax-exchange.github.io/disruptor/#_what_is_the_disruptor
Disrupter 组件构成:
![](https://static001.geekbang.org/infoq/8e/8e1cc97b81b888af70208bcd5a52d542.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
Disrupter 性能测试结果
![](https://static001.geekbang.org/infoq/99/99243ee3465a998912af05b6685721b2.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
如何使用异步日志
log4j2 开启异步日志的方法主要有以下两种方式:
1)全局异步日志
通过 JVM 启动参数来全局启用异步日志功能。在启动应用程序时,向 JVM 传递以下系统属性:
在类路径(classpath)中添加一个名为 log4j2.component.properties 的文件,并包含以下内容(这个文件会在 Log4j2 初始化时被读取):
这两种方式下,所有 Logger 都会自动使用异步处理。
2)混合异步日志
在 log4j2.xml 配置文件中,可以手动指定特定的 Logger 使用异步处理,通过将 <Root>或<Logger>元素替换为<AsyncRoot>或<AsyncLogger>。例如:
异步日志的潜在问题及解决方案
潜在问题:
日志丢失问题:如果机器发生意外重启、发布、掉电导致的 jvm 进程停止,停留在队列的未来得及输出到目的地的 LogEvent 可能会丢失
日志顺序问题:由于日志事件是在不同的线程中异步处理的,因此日志条目可能不会严格按照它们产生的顺序出现在日志文件中,这对于需要严格按时间顺序追踪日志的应用可能是个问题。
其他问题:如增加资源损耗、配置复杂度和调试复杂度等问题
解决方案:
对于日志丢失问题:
原生 Log4j2 有完整的生命周期管理,并监听了 jvm 关闭的事件。当 jvm 关闭时,Log4j2 会监听 Disrupter 队列中的 RingbufferLogEvent 数量,直到日志打印完(或超时)才释放关闭 Log4j2,jvm 才得以正常关闭。但是自然灾害或者机房掉电等不可抗力因素,无法避免丢失问题。
我们基于 Log4j2 定制的 AsyncAbleRollingFileAppender,其中有独立的 Disrupter,且不在 Log4j2 生命周期管理当中,存在日志丢失风险。可以采用类似方案解决:
AsyncAbleRollingFileAppender 使用独立的 disrupter,且 RingBufferLogEvent 未及时清理对象,容易导致内存泄漏,异步日志场景请慎用。
对于日志顺序性问题:
异步线程池大小设置为 1,但是会影响日志打印的速度(现在的普遍做法)。
延迟打印
三、效果
4 月份的这一问题发生后,我们从原理出发,对理财的核心应用做了升级和优化,整体服务耗时上取得了不错的性能优化效果。
应用 rpc 耗时:
![](https://static001.geekbang.org/infoq/40/406e4ab80e41082cc00300f8f71a0745.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
应用网关耗时:
![](https://static001.geekbang.org/infoq/fd/fde79507268e9c64c941ee859c478c9e.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
但与此同时,我们也发现升级后,应用的 fgc 次数更多了,经过 heapdump 分析后,发现 AsyncAbleRollingFileAppender 内部实现的 RingBufferLogEvent 执行后,不会释放引用的 LogEvent,导致 Disrupter 一直持有已打印的 LogEvent 的引用关系,进而导致了内存泄漏。后来,我们采取主动释放对象引用(RingBufferLogEvent.setLogEvent(null))优化的方案,发布以后前后 fgc 对比如下:
GC 优化前:
![](https://static001.geekbang.org/infoq/71/71d89613ecb3e4cf7708af8077f6207a.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
GC 优化后:
![](https://static001.geekbang.org/infoq/bf/bfe0e90231574e8439748537f00e4ae7.webp?x-oss-process=image%2Fresize%2Cp_80%2Fformat%2Cpng)
四、建议
日志作为诊断问题、监控系统健康状况与优化服务效能不可或缺的一环,其重要性不言而喻。熟练掌握并有效利用如 Log4j2 这样的高性能日志框架以及注意一些打印日志的策略(如动静分离、合理分割、合理设置日志级别等),对于开发者而言至关重要:
1)动静分离 :在一些大日志输出场景中,即使是异步日志也会给系统带来性能风险。因此建议合理识别大日志中的动态数据和静态数据。静态数据定时输出,动态数据关联唯一静态标识输出,在降低性能风险的同时又满足监控分析的需要;
2)合理分割 :日志文件需要合理分割,并设置合理的保留策略,及时释放磁盘空间。
3)合理设置日志级别 :避免日志滥用,尤其是 debug 日志,既有利于日志定位问题的速度,又能提高性能。
评论