文章链接: https://pengcheng.site/2019/11/17/log4j-he-log4j2-zai-springboot-zhong-de-xing-neng-dui-bi/
前言
在 java 项目中最常用的三大日志框架是logback，log4j，log4j2。其中logback是 springboot 的默认框架。由于历史原因，我手上有个springboot项目的日志框架是用的log4j。在对某个接口进行压测和性能优化的时候发现，打印同步日志会导致接口的性能缩水，所以当时直接把性能要求高的接口的日志关闭掉了。随着系统的逐渐复杂，重要性越来越高，定位问题的难度越来越大，我逐渐感觉到日志的的重要性。所以优化日志势在必行。
我是从两个方面来考虑优化日志这个问题的。
- 更换性能更高的日志框架；
- 使用异步日志或者延时刷盘的日志配置。
对第一个问题，很容易就可以Google到，目前性能表现最好的日志框架是log4j2，所以直接把日志框架替换成log4j2就可以了。
对于第二个问题，因为当前日志是同步的，需要把“打印日志”这个操作完成之后才会运行接下来的业务代码，而“打印日志”通常是要输出到控制台或者文件中的，IO开销很大，如果把这个过程变成异步的应该能从一定程度上提高性能表现。
不知道在哪听到的两句话，想在这里分享一下：
- 没有日志的系统就像在裸奔
- 没有uid的日志是没有灵魂的
PS：这里没有uid的本来是指是调用方的id，更一般的说法就是不能定位问题的日志是没有存在价值的。
环境
- springboot 2.1.5
- java 8
- MacBook Pro 2017
log4j日志
log4j 在 springboot 中的配置
在 springboot 中使用 log4j 需要引入其依赖并把 springboot 自带的日志框架 logback 排除掉:
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j</artifactId>
<version>1.3.8.RELEASE</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter</artifactId>
<exclusions>
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
然后编写配置文件log4j.properties:
log4j.rootLogger=INFO,stdout,file
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender
log4j.appender.file.File=logs/seller_penalty_api_server.log
log4j.appender.file.Append=true
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n
性能测试
知己知彼，百战不殆。
要对比性能，首先就要知道原来的log4j框架的性能表现如何。
这里我使用了一种简单的方式来进行对比。在 springboot 中实现两个简单的接口，一个打印一行日志，一个不打印日志，然后用wrk工具对接口进行压测，看两个接口能够达到的QPS分别是多少。
// 不打印日志
@GetMapping("/ping")
public String ping() {
return "pang";
}
// 打印日志
@GetMapping("pingLog")
public String pingWithLog() {
log.info("calling /pingLog");
return "pangLog";
}
压测配置如下，分别对两个接口进行多次压测，取三次作为采样结果。
wrk -t10 -c250 -d30s http://localhost:8080/ping
| 采样次数 | 1 | 2 | 3 |
|---|---|---|---|
| 不打印日志 | 21937.40 | 23570.31 | 22950.31 |
| 打印日志 | 7825.40 | 7848.33 | 7788.54 |
可以看到两种情况基本上有将近三倍的差距。我是用nohup后台运行的，如果直接使用java -jar运行，日志输出到文件的同时还会输出到控制台，这种情况QPS将进一步降低，大概在5k+左右。这也正是我们最开始为了接口性能选择关闭日志的原因
log4j2
引入log4j2（同log4j一样，要排除 springboot 自带的日志框架）：
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
<!-- 增加识别yaml格式依赖，加上这个才能辨认到log4j2.yml文件 -->
<dependency>
<groupId>com.fasterxml.jackson.dataformat</groupId>
<artifactId>jackson-dataformat-yaml</artifactId>
</dependency>
然后在src/main/resources/路径中编写log4j2的配置文件。默认配置文件名是log4j2，支持xml、properties、json、yaml多种文件格式，这里我选了yml，所以需要额外引入jackson-dataformat-yaml的包。
Configuration:
status: debug
appenders: # 包含控制台和文件两个appender
Console:
name: LogToConsole
PatternLayout:
Pattern: "%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n"
RollingFile:
- name: LogToRollingFile
fileName: logs/seller_penalty_api_server.log
filePattern: "logs/seller_penalty_api_server.log.%d{yyyy-MM-dd}.gz" # 带有后缀名会自动压缩
PatternLayout:
pattern: "%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n"
Policies:
TimeBasedTriggeringPolicy: # 基于时间的trigger，每天一个文件
interval: 1
Loggers:
logger:
- name: io.shopee.bigdata.penalty.server
level: debug
additivity: false
AppenderRef:
- ref: LogToConsole
- ref: LogToRollingFile
Root:
level: error
AppenderRef:
ref: LogToConsole
使用log4j2之后，使用wrk和同样的参数压测（关掉控制台输入），三次测试的QPS分别是：
| 采样次 | 1 | 2 | 3 |
|---|---|---|---|
| QPS | 13992.50 | 15562.27 | 15161.16 |
可以看到在这个简单的场景下，性能几乎是log4j的2到3倍之多！所以很明显，首先替换日至框架是一个明智的选择。
log4j2 异步日志
到目前为止，上述的测试都是针对同步日志进行的测试。在确定了log4j2作为日志框架之后，我想看一下，使用异步日志能不能进一步提高性能表现。
AsyncAppender 和 Asynchronous Loggers
在log4j2中异步日志有两种实现AsyncAppender 和 Asynchronous Loggers
前者是 log4j2 最开始的异步日志实现，它把其他 Appender 作为输入，然后把产生 logEvent输出到默认的容器ArrayBlockingQueue中，然后使用另外一个线程中来输出日志以实现异步。但是官方文档也指出：
在这种多线程应用的实践中需要主要：阻塞队列很容易发生锁争用，测试表明当大量线程并发写日志的时候，性能甚至会变得更糟糕。所以应该考虑使用无锁的Asyn Loggers进行优化。
上述的Asyn Loggers是log42 团队后来才加入的异步实现，连官方文档都推荐它了，那还有什么好犹豫的呢。它需要引入一个额外的依赖：
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.4.2</version>
</dependency>
Disruptor 通过CAS而不是锁实现多生产者、多消费者对RingBuffer的并发访问，实现高吞吐和高性能。
它们两者的具体区别可以参考参考资料2
全异步和混合异步
Log4j2的异步日志的使用又可以分为全异步和混合异步，所谓全异步就是所有的日志都以异步方式输出；混合异步就是只有指定的代码文件用异步方式输出，其他日志使用同步方式输出；前者能够获得更高的性能，也是官方推荐的方式，后者具有更好的灵活性，可以进行针对性配置。
本文中我们直接使用全异步日志。
在springboot中开启全异步的方式很简单，只需要在配置文件中加如下配置（yml）：
log4j2:
contextSelector: org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
或者在用java -jar 启动的时候加入系统参数：
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
应用启动之后按照上述的方法测试接口性能：
| 采样次 | 1 | 2 | 3 |
|---|---|---|---|
| QPS | 16238.76 | 16006.78 | 16322.12 |
可以看到把日志从同步改成异步之后，性能有一定提升，但是并没有想象中那么大。
总结
- 同步日志和业务逻辑在同一个线程中，当日志输出完毕才能执行接下来的代码，涉及到IO，非常影响性能；
log4j2在本文的简单场景中性能要远远高于log4j，这次替换是值得的；log4j2异步日志应该使用Asynchronous Loggers而不是AsyncAppender- 本次测试是基于一个很简单的场景，在官方文档中，异步日志的性能要远远超过同步日志的，但是在本次测试中并没有体现出来；日志在 springboot 中的性能可能受多个方面的影响，比如每个调用链中日志的条数、springboot本身的配置，日志的level、硬件环境等。
- 项目代码见Github
彩蛋1-性能测试需要注意的点
关于性能测试，在 log4j2 的官方文档中提到的几点我觉得是比较通用的:
- 获取性能的采样结果之前需要 warm up the JVM；
- 重复热身多次，然后等待IO线程赶上并释放缓冲区;
- 测试的时候重复多次取平均数。
总结一下就是系统刚启动的一段时间的测试数据不能作为参考，需要压测一段时间，取稳定之后的结果。就像运动前的热身一样，不光JVM，各种线程池或连接池都需要一段时间的请求才能启动起来进入正常工作状态。
彩蛋2-springboot 中多环境日志配置
在springboot中我们通常针对dev，test，live等多种环境会有多套配置文件，比如application-dev.yml,application-test.yml, application-live.yml。然后可以在启动的时候可以通过在全局配置文件application.yml指定某个配置文件来启用配置：
sping:
profiles:
active: live
日志同样有这样的需求，不同环境使用不同的日志配置，比如dev或test环境需要开启的log level为DEBUG，而在live环境中却不需要。这种时候我们只需要写多套日志配置，比如log4j2-dev.yml，log4j2-test.yml，log4j2-live.yml，然后在其对应的配置文件中启用日志配置就可以了：
logging:
config: classpath:log4j2-dev.yml
参考资料
- Spring Boot Log4j 2 example
- Log4j2中的同步日志与异步日志
- Difference between Asynclogger and AsyncAppender in Log4j2
- https://www.callicoder.com/spring-boot-log4j-2-example/
原文发表于：https://pengcheng.site/2019/10/28/springboot-zi-dong-pei-zhi-qian-xi/