Java日志框架对比分析及性能调优

---

前言

本文针对Log4j2和Logback框架进行深入解析，通过性能压测、热点图及源码方式，分析两者优劣势及产生性能差距原理，在最后总结Log4j2性能调优的方式

---

一、日志处理流程

下面按日志记录的流程，分析每一步处理的内容及性能损耗

1. 整体流程

日志记录的流程如下：

1. 提交日志：业务代码内调用Logger记录日志
2. 输入日志：Logger把日志移交到Appender
3. 输出日志：
   1. 同步Appender继续完成输出（落盘、网络提交、控制台输出等）
   2. 异步Appender将日志放入Queue中，等待消费者处理消费者从Queue取出日志，并进行输出

同步日志

串行地执行日志输入到输出过程。对业务调用方来说，每次日志记录耗时=输入耗时+输出耗时，因此Appender的性能直接地影响业务方耗时

异步日志

Logback通过AsyncAppender实现异步输出。相比同步的优势在于，对业务方具有更短的响应时间，异步把消息存入队列就返回。

2. 输入日志

由业务调用Logger对象，并进行过滤、缓存、调用输出等操作。

Logback

Logback输入日志流程如下：（总耗时约15μs）

1. 日志记录：业务方调用Logger对象的info/debug等方法，进行日志记录。（约1μs）
2. 日志过滤：Logger首先在内部进行日志等级过滤，低于配置的日志等级，将直接返回跳过后续处理。（约5μs）
3. 事件构建：Logger根据info/debug等方法传入的形参，构建LoggingEvent对象。（约5μs）
4. 事件通知：从子类到父类遍历Logger树，对每个Looger调用appendLoopOnAppenders。（约4μs）
5. 遍历输出：遍历Logger内每个Appender进行输出。（耗时根据Appender而定）

流程耗时：

调用链路：
总结：输入流程无密集计算逻辑和无阻塞，耗时较短，主要耗时受Appender影响。

Log4j2

3. 输出日志

从上游接Logger收到日志事件，到完成输出（落盘、发送等）的流程。

Logback

AsyncAppender

异步输出器，提供低时延的输出，日志输入后等待短时间就能得到响应（约18μs）。通过队列、日志淘汰策略等机制实现低时延的响应。

异步日志输出流程如下：

1. 日志过滤：Appender接收到LoggingEvent后，会根据自身内部配置进行日志过滤。（约3μs）
2. 检查队列容量：获取锁后判断队列是否已满，如果队列溢出则过滤INFO等级以下日志。（约1μs，但可能被阻塞）
3. 预处理：执行内容消息、获取MDC属性、记录调用者信息等。（约2μs）
4. 存入队列：先获取到锁，再向队列放入日志事件。(约2μs，但可能被阻塞）
5. 提取日志：消费者线程先获取到锁，然后从队列取出日志事件（约1μs，但可能被阻塞）
6. 下发日志：根据AsyncAppender配置的下游进行分发，将日志事件发放到每个下游（耗时受下游Appender影响）

调用链路：
流程耗时：

对业务来说，日志记录耗时=输入耗时+部分输出耗时，约等于23μs。但如果产生线程阻塞将直接地影响业务方。

总结：
在日志输出阶段中如果产生阻塞，检查容量和存入队列步骤直接影响业务方，取出日志虽然不直接影响业务方，但会降低日志消费能力，造成日志淘汰或者业务方阻塞问题

锁争抢

BlockArrayQueue队列每次向栈顶放入元素都会先获取锁，锁是通过ReentrantLock实现的非公平锁，因此在多个生产者并发存入日志会发生锁争抢，产生上下文切换消耗，影响响应时间

下图是通过JProfiler监控调用，并使用JMeter模拟并发访问

检查容量时，锁抢占产生阻塞：
取出日志时，锁抢占产生阻塞：

总结：在并发场景下，每个执行日志记录的线程，都需要争抢同一个锁来存放到队列，因此Logback在多线程场景性能较差。

FileAppender

ConsoleAppender

---

总结

提示：这里对文章进行总结：
例如：以上就是今天要讲的内容，本文仅仅简单介绍了pandas的使用，而pandas提供了大量能使我们快速便捷地处理数据的函数和方法。