技术攻关系列：Log4j1升级Log4j2实战

Posted 2021-04-20 云时代架构

这是在公司内部的一次升级实践，删除了很多隐私的内容，所以可能不是很完整。

1、背景

在任何系统中，日志都是非常重要的组成部分，它是反映系统运行情况的重要依据，也是排查问题时的必要线索。绝大多数人都认可日志的重要性，但是又有多少人仔细想过该怎么打日志，日志对性能的影响究竟有多大呢？

新的Log4j 2.0版本有了大幅的性能提升、新的插件系统，以及配置设置方面的很多改善。Log4j 1.x 在高并发情况下出现死锁导致cpu使用率异常飙升，而Log4j2.0基于LMAX Disruptor的异步日志在多线程环境下性能会远远优于Log4j 1.x和logback ——官方测试结果。

本次升级是以thrift服务化项目为例子进行的，后续会在其他项目中进行，本次工作内容为：Log4j1.x 升级到 Log4j2（如果不想了解原理，可以直接跳到：3、升级方式）

2、log4j2说明

2.1 特性

• API分离: Log4j2将API与实现分离开来(log4j-api： 作为日志接口层，用于统一底层日志系统,log4j-core : 作为上述日志接口的实现，是一个实际的日志框架)

• 改进的特定: Log4j2的性能在某些关键领域比Log4j 1.x更快，而且大多数情况下与Logback相当。

• 多个API支持：Log4j2提供最棒的性能的同时，还支持SLF4J和公共日志记录API。

• 自动配置加载：像Logback一样，一旦配置发生改变，Log4j2可以自动载入这些更改后的配置信息，又与Logback不同，配置发生改变时不会丢失任何日志事件。

• 高级过滤功能：与Logback类似，Log4j2可以支持基于上下文数据、标记，正则表达式以及日志事件中的其他组件的过滤。

• 插件架构：所有可以配置的组件都以Log4j插件的形式来定义。无需修改任何Log4j代码就可以创建新的Appender、Layout、Pattern Convert 等等。Log4j自动识别预定义的插件，如果在配置中引用到这些插件，Log4j就自动载入使用。

• 属性支持：属性可以在配置文件中引用，也可以直接替代或传入潜在的组件，属性在这些组件中能够动态解析。属性可以是配置文件，系统属性，环境变量，线程上下文映射以及事件中的数据中定义的值。用户可以通过增加自己的Lookup插件来定制自己的属性。

• log4j2配置: 不支持properties文件,但却可以以json文件作为配置

2.2 性能

吞吐量测试

image.png

平均耗时

image.png

其中：

Loggers mixed sync/async: 同步与异步logger可以混合使用，分别由标签<logger> <asyncLogger> 指定
异步Logger与异步Appender区别：AsyncAppender使用ArrayBlockingQueue来处理message，AsyncLogger使用LMAX Disruptor

• AsyncAppender的做法是：应用线程创建LogEvent将其塞入Queue，消费线程取出LogEvent写磁盘。在这种框架的可扩展性不好，当加倍消费线程时各个线程的吞吐量会减半，所以总吞吐量并不会得到增加。原因是，并发queue是标准java库的一部分，会使用锁来保证数据传递的正确性。

• LMAX Disruptor是一个无锁数据结构，可以在线程间传递消息。详细介绍可访问其网站：https://github.com/LMAX-Exchange/disruptor/wiki/Introduction

更多性能测试信息可参考官方报告：
http://logging.apache.org/log4j/2.x/manual/async.html#Performance
http://logging.apache.org/log4j/2.x/performance.html

2.3 主要组件

image.png

2.4 配置

Configuration

示例：

<?xml version="1.0" encoding="UTF-8"?><Configuration>    <Properties>        <Property name="pattern_layout">%d %-5p (%F:%L) - %m%n</Property>        <Property name="LOG_HOME">/var/***/logs</Property>    </Properties>    <Appenders>        <Console name="console" target="SYSTEM_OUT" follow="true">            <PatternLayout pattern="${pattern_layout}"/>        </Console>        <RollingRandomAccessFile name="file"                                 fileName="${LOG_HOME}/${sys:app.key}.log"                                 filePattern="${LOG_HOME}/${sys:app.key}.log.%d{yyyy-MM-dd}">            <PatternLayout pattern="${pattern_layout}"/>            <Policies>                <TimeBasedTriggeringPolicy/>            </Policies>        </RollingRandomAccessFile>        <RollingRandomAccessFile name="access_kpi"                                 fileName="${LOG_HOME}/${sys:app.key}_access_kpi.log"                                 filePattern="${LOG_HOME}/${sys:app.key}_access_kpi.log.%d{yyyy-MM-dd}">            <PatternLayout pattern="${pattern_layout}"/>            <Policies>                <TimeBasedTriggeringPolicy/>            </Policies>        </RollingRandomAccessFile>        <RollingRandomAccessFile name="jmonitorappender"                                 fileName="${LOG_HOME}/${sys:app.key}.jmonitor.log"                                 filePattern="${LOG_HOME}/${sys:app.key}.jmonitor.%d{yyyy-MM-dd}.log.gz">            <PatternLayout pattern="${pattern_layout}"/>            <Policies>                <TimeBasedTriggeringPolicy/>            </Policies>        </RollingRandomAccessFile>        <RollingRandomAccessFile name="jmonitorlogstoreappender"                                 fileName="${LOG_HOME}/${sys:app.key}.jmonitor.logstore.log"                                 filePattern="${LOG_HOME}/${sys:app.key}.jmonitor.logstore.%d{yyyy-MM-dd}.log.gz">            <PatternLayout pattern="${pattern_layout}"/>            <Policies>                <TimeBasedTriggeringPolicy/>            </Policies>        </RollingRandomAccessFile>        <Scribe name="errorLog">            <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>            <Property name="hostname">${sys:app.key}</Property>            <Property name="scribeHost">127.0.0.1</Property>            <Property name="scribePort">4252</Property>            <Property name="scribeCategory">cos_errorlog</Property>            <Property name="printExceptionStack">false</Property>            <Property name="addStackTraceToMessage">false</Property>            <Property name="timeToWaitBeforeRetry">6000</Property>            <Property name="sizeOfInMemoryStoreForward">100</Property>            <PatternLayout                    pattern="%d %p $${sys:app.host} $${sys:app.ip} errorlog appkey=$${sys:app.key} location=%F:%L rawlog=%replace{%replace{%m}{=}{:}}{
|	}{<br/>} rawexception=%replace{%replace{%ex}{=}{:}}{
|	}{<br/>}%n"/>        </Scribe>    </Appenders>    <Loggers>        <Logger name="access_kpi" level="INFO" includeLocation="true" additivity="false">            <AppenderRef ref="access_kpi"/>        </Logger>        <!-- tair Loggers -->        <Logger name="com.taobao.tair3.client"  level="WARN" includeLocation="true" additivity="false">            <AppenderRef ref="file"/>            <AppenderRef ref="errorLog"/>        </Logger>        <!-- 3rdparty Loggers -->        <Logger name="org.springframework" level="WARN"/>        <Logger name="org.apache.zookeeper" level="ERROR"/>        <Logger name="org.springframework.web" level="WARN"/>        <!-- Root Logger -->        <Root level="INFO" includeLocation="true">            <AppenderRef ref="file"/>            <AppenderRef ref="console"/>            <AppenderRef ref="errorLog"/>        </Root>    </Loggers></Configuration>

我们先看看Configuration的一些特性：

• Configuration代表Log4j2的配置文件，它和LoggerContext组件一一对应（关于LoggerContext请看下文），它维护Log4j2各个组件之间的关系，其中，一个Configuration对应多个LoggerConfig组件。

• Configuration可以通过四种方式配置：a）配置文件（XML、JSON和YAML）；b）创建ConfigurationFactory和Configuration实现；c）通过代码调用Configuration的API构造；d）在Logger内部调用API函数构造。

• Configuration能够在应用程序初始化的过程中进行自动装配，其配置内容按照一定的顺序获取，详见：AutomaticConfiguration。

• 当我们给Configuration设置monitorInterval时，这可以使得log4j2阶段性的读取配置文件，并重新构造Configuration。在这一过程中，log4j2不会丢失日志事件。

Configuration标签

<Configuration status="WARN">
  ...</Configuration>

该片段表明log4j2配置文件的所有内容都在这个标签内，其status属性为“WARN”说明：log4j2内部的日志会将日志级别大于WARN的日志打印到Console。除了该字段，Configuration还包括其他属性，详见：ConfigurationSyntax。

Appenders标签

<Appenders>    <Console name="Console" target="SYSTEM_OUT">      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>    </Console></Appenders>

所有的Appender将在<Appenders>和</Appenders>之间定义。上述例子定义了ConsoleAppender并关联PatternLayout，关于Appender和Layout请看上述相关小节。

Logger标签

<Loggers>
    <Logger name="com.foo.Bar" level="trace" additivity="false" includeLocation="true">
      <AppenderRef ref="Console"/>
    </Logger>
    <Root level="error">
      <AppenderRef ref="Console"/>
    </Root></Loggers>

所有的Logger将在<Loggers>和</Loggers>之间定义。上述例子通过<Root>定义了所有Logger的根结点(RootLogger)，并通过<AppenderRef>标签关联名称为“Console”的Appender，关于Logger请看上述相关小节。

此处有必要说明additivity字段，通过配置该字段，我们可以规定是否将日志事件传递到Logger的父结点处理，其默认值为true（即默认交给parent Logger处理）。

Logger默认不会获取location信息，因此，若我们的Layout或Filter等需要location信息，我们必须给相应的设置“includeLocation=true”

Filters标签

<Filters>
    <Marker marker="EVENT" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
    <DynamicThresholdFilter key="loginId" defaultThreshold="ERROR" onMatch="ACCEPT" onMismatch="NEUTRAL">
      <KeyValuePair key="User1" value="DEBUG"/>
    </DynamicThresholdFilter></Filters>

log4j2还有一个很重要的组件——Filter，详见Filter小节。此处通过<Filters>和</Filters>表明这是一个组合Filter，里边包括MarkerFilter和DynamicThresholdFilter。onMatch表示和onMismatch表示经过Filter过滤后的结果，该结果有三个取值：ACCEPT、NEUTRAL和DENY。log4j2在处理LogEvents时，会通过该Filter进行过滤，若返回结果为ACCEPT，则直接处理（略过其它Filter和日志级别的过滤）；若返回DENY则直接终止该LogEvents；若返回NEUTRAL，则不做决策，让后续代码做处理。

此处，Filter是通过Configuration的直接子元素配置，因此，LogEvents若被该Filter过滤之后则不会传递给Logger处理。

2.5 异步日志

Log4j2提供了异步Logger，通过不同线程实现I/O操作，目的在于为我们的应用程序提高性能。我们先来看一看它主要在哪些方面做改进：

1. Asynchronous Loggers。异步日志器是Log4j2新增的日志器，它的目的是让我们的应用程序在调用Logger.log()打印日志时立马返回。我们可以在程序中全部使用异步日志器，也可以使用混合的日志器，前者能给我们的程序带来很大的性能提升，而后者让我们的程序足够灵活。

2. LMAX Disruptor技术。异步日志器在其内部实现采用了Disruptor技术，相对于使用BlockingQueue，它提高了吞吐量和降低延时。

3. Asynchronous Appender。该组件在Log4j1.x已经存在，但是Log4j2实现的异步Appender使得每次写入磁盘时，都会进行flush操作，效果和配置“immediateFlush=true”一样。该异步Appender内部采用ArrayBlockingQueue的方式，因此不需要引入disruptor依赖。

4. RandomAccessFileAppender。该Appender采用ByteBuffer+RandomAccessFile替代了BufferedOutputStream，官方给出的测试数据是它将速度提升了20-200%。

AsyncLoggers虽然带来了极大的性能提升，我们应该经常使用。不过，它也有一些缺点，因此，我们要根据具体的应用场景决定使用同步还是异步的方式，详见：Trade-offs。

3、升级方式

以下开始说明*服务化项目如何由：Log4j1.x 升级到 Log4j2

3.1 排除对log4j的依赖

需要确定项目pom文件中依赖的其他的jar中也不再依赖log4j及slf4j-log4j12，具体方式可以通过IDE提供的功能或者直接使用mvn dependency:tree确定依赖关系。

由于引用的jar中很多依然使用的为log4j，因此已经升级过log4j2的项目，每次在新增依赖的时候，一定需要确定一下，引用的jar是否含有对低版本的依赖，并且exclusion掉。

<exclusions>
    <exclusion>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
    </exclusion>
    <exclusion>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
    </exclusion></exclusions>

3.2 添加对log4j2的依赖

<properties>    <org.slf4j-version>1.7.12</org.slf4j-version>    <log4j2-version>2.3</log4j2-version></properties><dependency>    <groupId>org.slf4j</groupId>    <artifactId>jcl-over-slf4j</artifactId>    <version>${org.slf4j-version}</version>    <scope>runtime</scope></dependency><dependency>    <groupId>org.apache.logging.log4j</groupId>    <artifactId>log4j-1.2-api</artifactId>    <version>${log4j2-version}</version></dependency><dependency>    <groupId>org.apache.logging.log4j</groupId>    <artifactId>log4j-slf4j-impl</artifactId>    <version>${log4j2-version}</version></dependency><dependency>    <groupId>org.apache.logging.log4j</groupId>    <artifactId>log4j-api</artifactId>    <version>${log4j2-version}</version></dependency><dependency>    <groupId>org.apache.logging.log4j</groupId>    <artifactId>log4j-core</artifactId>    <version>${log4j2-version}</version></dependency><dependency>    <groupId>com.lmax</groupId>    <artifactId>disruptor</artifactId>    <version>3.2.0</version></dependency><dependency>     <groupId>com.sankuai.meituan</groupId>     <artifactId>scribe-log4j2</artifactId>     <version>1.0.9</version></dependency>

3.3 JVM参数

在JVM启动参数中增加 -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 开启异步日志。（目前针对scribe的appender为同步appender，如果不开启异步机制会导致线程block）

3.4 XML配置

删除原log4j.xml配置文件，新增log4j2.xml，注意：需要保证log4j2.xml在resource根目录内，否则会导致配置文件加载不到（即log4j2.xml需要在class根目录内）

注意事项

1. includeLocation:Logger默认不会获取location信息，因此，若我们的Layout或Filter等需要location信息，我们必须给相应的设置“includeLocation=true”

2. additivity:通过配置该字段，我们可以规定是否将日志事件传递到Logger的父结点处理，其默认值为true

3. file文件的路径，由于启动脚本及服务器变量配置等的不确定性，因此该处建议直接配置绝对路径，可以使用<Property name="LOG_HOME">/var/*/logs</Property>配置在xml中，也可以通过JVM参数 -Dapp.logdir=$LOG_HOME等方式

4. AsyncLogger为异步日志，需要添加JVM参数-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

5. 服务化项目启动脚本里如果对启动日志做重定向了“>> $LOGDIR/$LOGFILE 2>&1”，请不要使用Console输出日志，否则会导致重定向的日志文件将重复打印所有日志信息

6. 服务化项目不需要配置access_kpi的日志打印

7. Scribe说明（线上异常监控接入说明#线上异常监控接入说明-log4j2.0）

• hostname：这里获取的是java启动时配置的系统参数

• scribeCategory：这里写死“cos_errorlog”，这样数据组才知道这套日志需要发送给sg-errlog系统

• pattern：按照数据组的要求打印日志，同时将“等号”和“回车”等替换为对应的占位符

• scribeHost:scribeHost:测试环境为10.4.232.70,如果服务器上有采集器监听,则可以配置127.0.0.1

3.5 Log定义

private static final Logger LOGGER = LoggerFactory.getLogger(Boot.class);

使用slf4j进行log的定义，注意需要保证项目中不再依赖于slf4j1。如果启动时有如下提示，说明依然依赖了多个slf4j

image.png

4、参考资料

http://logging.apache.org/log4j/2.x/manual/migration.html#Configuring_Log4j_2http://logging.apache.org/log4j/2.x/guidelines.htmlhttp://logging.apache.org/log4j/2.x/performance.htmlhttp://www.infoq.com/cn/articles/things-of-java-log-performancehttp://www.infoq.com/cn/news/2014/08/apache-log4j2




长按下面二维码关注更多云时代架构文章！