EZLippi-浮生志

Log4j升级到Log4j2

我们的系统一直用的是公司统一的日志类来打印日志,看了下内部实现,仅仅是对Slf4j门面+Log4j这套做了一些封装,加入了扩展的能力,各个模块在扩展点文件中配置日志路径、级别和包名,由工具类动态生成日志配置文件,由于一直没出问题所以没太关注,但是最近有个环境经常出现响应慢、Full GC频繁的问题,我在分析线程堆栈时发现了2个问题:一个是Log4j打日志有一定概率会出现死锁;另一个是有个缓存类调用非常频繁,很多线程都卡在打印日志那里,分析了下发现Log4j里每个Logger对象一把锁,同一个类里面打印日志的方法只能串行执行,效率非常低,经过研究对比了几个日志框架之后决定先把我们组的日志框架迁移到Log4j2,后面在部门内推广使用。

Log4j死锁问题

在Log4j 1.x版本中同步打印日志的时候,在高并发场景下会出现死锁导致cpu使用率异常飙升,其原因是当线程写日志的时候需要获取到Logger和Appender,org.apache.log4j.Logger类继承于org.apache.log4j.Category、Appender继承于org.apache.log4j.AppenderSkeleton。通过Log4j 1.x中Category源码和Appender源码可以知道,当多线程并发时,可能会因为相互持有Logger和Appender发生死锁,而且同一个Logger对象只能串行打印日志,在高并发场景会容易引起性能问题。

看下打印日志的过程,调用Logger类打印日志的方法会调用Category的callAppenders()方法,这个方法会锁住Category对象,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public void callAppenders(LoggingEvent event) {
int writes = 0;

for(Category c = this; c != null; c = c.parent) {
synchronized(c) {
if (c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}

if (!c.additive) {
break;
}
}
}
}

上面这段代码最终会调用到AppenderSkeleton的doAppend()方法,可以看到doAppend()是个同步方法,也就是说打印一条日志要先后获取两个对象同步锁,在高并发的情况下,两次lock就很容易造成死锁,特别是在业务逻辑里面如果还有其他获取锁的逻辑死锁的概率就更高了。

1
public synchronized void doAppend(LoggingEvent event) {//省略 }

整个流程如下所示:

Log4j2的优点

Log4j2是Log4j 1.x的升级版,与之前的版本Log4j 1.x相比、有重大的改进,主要变更点总结在下表:

优化点 说明
API实现分离 Log4j2将API与实现分离开来,原先Log4j 1.x版本只需引入log4j的依赖,Log4j2版本需要引入log4j-api和log4j-core两个依赖
自动加载新的配置 Log4j 2.x 和Logback都新增了自动加载日志配置文件的功能,而且配置发生改变时不会丢失任何日志事件,可以在Configuretion中设置monitorInterval设置检查配置文件变更的时间间隔
支持变量参数的占位符功能 Log4j2和Slf4j一样,支持支持变量参数的占位符功能,对字符串打印和输出做了很多优化,新的Markers和flow tracing可以帮助追踪程序工作流
性能较大提升 Log4j2相对于Log4j 1.x,具有更快的执行速度,由于重写了内部的实现,在某些特定的场景上面,甚至可以比之前的速度快上10倍,比如内部的消息队列采用ArrayBlockingQueue,相对于原始的ArrayList和锁操作来说,管程类的消息队列拥有更好地性能
异步性能 Asynchronous Loggers是Log4j2新增的日志器,异步日志器在其内部实现采用了LMAX Disruptor(一个无锁的线程间通信库)技术,Disruptor主要通过环形数组结构、元素位置定位和精巧的无锁设计(CAS)实现了在高并发情形下的高性能
死锁问题的解决 log4j 2.x中充分利用Java5的并发支持,并且以最低级别执行锁定

Slf4j静态绑定介绍

Slf4j作为一个日志门面,提供统一的打印日志接口,使得用户能够很方便的使用和切换想要的logging实现框架;静态绑定的实现是通过提供一个适配层,每个日志实现框架如果要适配Slf4j的api,那就提供一个适配Slf4j门面的适配包,适配包里都有一个包名和类名都相同的类org.slf4j.impl.StaticLoggerBinder,这个类的功能就是调用具体的日志库;SLF4j的使用者只要把适配包和slf4j-api的jar包放入classpath中,打印日志时LoggerFactory调用StaticLoggerBinder类中的getLoggerFactory()方法返回相应的ILoggerFactory实例,最后通过ILoggerFactory实例获取Logger具体实例,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
public interface LoggerFactoryBinder {

public ILoggerFactory getLoggerFactory();

public String getLoggerFactoryClassStr();

}
public interface ILoggerFactory {
//适配包里的getLogger方法会返回一个适配了slf4j接口的Logger
public Logger getLogger(String name);

}

下面这个图片是官网提供的常见的一些log实现和绑定:

需要注意的是Slf4j在classpath下只支持一个适配包(slf4j-simple、slf4j-log4j12、slf4j-jdk14、logback-classic、log4j-slf4j-impl等)。如果在classpath下存在多个桥接包,Slf4j会随机加载一个,把加载出来的适配包打印出来,如下所示:

1
2
3
4
5
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/bjwanghanbing/.m2/repository/org/slf4j/slf4j-log4j12/1.7.6/slf4j-log4j12-1.7.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Users/bjwanghanbing/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.8.2/log4j-slf4j-impl-2.8.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]

Log4j2与Slf4j集成

除了添加slf4j-api外,还需要添加与slf4j门面集成的适配器log4j-slf4j-impl,maven配置如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
<!-- Slf4j门面 -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.7.6</version>
</dependency>
<!-- 桥接:告诉Slf4j使用Log4j2 -->
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>2.8.2</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.8.2</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.8.2</version>
</dependency>
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.3.4</version>
</dependency>

Log4j2配置

Log4j2的配置和Log4j 1.x版本有较大区别,可以参考log4j2的官方文档,这里给出一个例子:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
<?xml version="1.0" encoding="UTF-8"?>
<!--日志级别以及优先级排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
<!--Configuration后面的status,这个用于设置log4j2自身内部的信息输出,可以不设置,当设置成trace时,你会看到log4j2内部各种详细输出-->
<!--monitorInterval:Log4j能够自动检测修改配置 文件和重新配置本身,设置间隔秒数-->
<configuration status="WARN" monitorInterval="30">
<!--先定义所有的appender-->
<appenders>
<!--这个输出控制台的配置-->
<console name="Console" target="SYSTEM_OUT">
<!--输出日志的格式-->
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss:SSS}] [%p] [%t] [%C %L] %m%n"/>
</console>

<!--文件会打印出所有信息,这个log每次运行程序会自动清空,由append属性决定,这个也挺有用的,适合临时测试用-->
<!--<File name="log" fileName="log/log4j2.log" append="false">
<PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>
</File>-->


<!--这个会打印出所有的info及以上级别的信息,每次大小超过size,则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩,作为存档-->
<RollingFile name="RollingFileInfo" fileName="${sys:user.home}/log4j.log"
filePattern="${sys:user.home}/${date:yyyy-MM}/log4j-%d{yyyy-MM-dd}-%i.log">

<!--控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch)-->
<Filters>
<ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
</Filters>
<!-- %d打印日期 %p打印日志级别 %t打印线程名称 %C全限定类路径 %L行号(效率较低) %m日志详情 %n换行-->
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss:SSS}] [%p] [%t] [%C %L] %m%n"/>
<Policies>
<!--基于时间的滚动策略,interval属性用来指定多久滚动一次-->
<TimeBasedTriggeringPolicy/>
<!--基于指定文件大小的滚动策略,size属性用来定义每个日志文件的大小-->
<SizeBasedTriggeringPolicy size="20 MB"/>
</Policies>
<!--指定同一个文件夹下最多有几个日志文件时开始删除最旧的,创建新的-->
<DefaultRolloverStrategy max="10"/>
</RollingFile>
<!--异步Appender,默认用ArrayBlockingQueue来缓存日志,不需要使用disruptor三方件-->
<Async name="ASYNC" bufferSize="262144" includeLocation="true">
<AppenderRef ref="RollingFileInfo"/>
</Async>
</appenders>
<!--然后定义logger,只有定义了logger并引入的appender,appender才会生效-->
<loggers>
<!--异步Logger,需要引入disruptor-3.3.4.jar,
如果要全部都开启异步日志,要设置系统属性
log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
如果配置了log4j2.contextSelector系统属性,那在logger配置中不要使用asyncRoot和asyncLogger,否则会把异步和异步Logger混用,
就会导致有两个后台线程,参考:https://logging.apache.org/log4j/2.x/manual/async.html-->

<!--过滤掉spring的一些无用的DEBUG信息-->
<!--<AsyncLogger name="org.springframework" level="info" includeLocation="true">
<AppenderRef ref="Console"/>
</AsyncLogger>-->

<Root level="info" includeLocation="true">
<appender-ref ref="ASYNC"/>
</Root>
</loggers>
</configuration>

参考文档

log4j2-configuration

Log4j 2.x 日志升级的详细流程

深入源码之SLF4J

🐶 您的支持将鼓励我继续创作 🐶