是时候将日志框架升级到Log4j2了

Posted by Yezhiwei on October 4, 2018

为什么要升级

现在维护的公司项目,在不同的时期使用了不同的日志框架,最早的 Log4j,前两年开始使用 Spring Boot ,日志使用了 Logback,最近看到一些介绍 Log4j2 的文章和官方的性能测试对比。所以计划在未来的新项目中使用 Log4j2,及旧项目的日志升级为 Log4j2 。在实践的过程中也遇到了一些问题,下面做一个简单的记录。

旧项目的日志使用的Log4j

  • 一般,在生产环境的日志级别会设置为 INFO (优先级从高到低依次为:FATAL、ERROR、WARN、INFO、DEBUG、TRACE), 低于这个级别的日志不会输出,但是下面这段代码,即使不输出,也会执行字符串的拼接
log.debug("param1 = " + param1 + ", param2 = " + param2);

所以为了不必要的性能损耗,需要加上判断:

if (log.isDebugEnable) {
    log.debug("param1 = " + param1 + ", param2 = " + param2);
}
  • Log4j的另一个问题是:日志并发输出的时候,发现大量的处理线程blocked 在等待同一个 log4j 的 rootLogger 对象锁,所以会锁等待,在高并发且日志输出频繁的情况下,这个锁等待的情况会很严重,进而影响了应用的性能表现。

Spring Boot 默认日志配置

  • 默认日志 Logback
  • Logback 是 Log4j 框架的作者开发的新一代日志框架,它效率更高、能够适应诸多的运行环境,同时天然支持 slf4j。
  • 定义了日志的切分方式,如:把每一天的日志归档到一个文件中。
  • 表示只保留最近30天的日志,以防止日志填满整个磁盘空间。

Log4j2及其优势

直到看到了一篇文章《詹嵩:性能牛逼的Log4j2是个什么鬼》,才决定再次对 Logback 进行升级。

升级过程与遇到的问题

先体验一下使用 Lo4j2 的 Demo, 然后再聊升级的问题

添加依赖

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.6.2</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.6.2</version>
</dependency>

Log4j2 默认会在 classpath 目录下寻找 log4j.json、log4j.jsn、log4j2.xml 等名称的文件,如果都没有找到,则会按默认配置输出到控制台,并输出如下提示:

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.

最简单的配置

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Root level="error">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>

如上面的配置,我们添加的配置文件 log4j2.xml,以 Configuration 为根节点,有一个 status 属性,这个属性表示 log4j2 本身的日志信息打印级别。如果把 status 改为 TRACE 再执行测试代码,可以看到控制台中打印了一些 log4j 加载插件、组装 logger 等调试信息(一般设置为 OFF )。 日志级别从低到高分为 TRACE < DEBUG < INFO < WARN < ERROR < FATAL,如果设置为 WARN,则低于 WARN 的信息都不会输出。对于Loggers 中 level 的定义同样适用。

下面是 Appender 配置,Appender 可以理解为日志的输出目的地,这里配置了一个类型为 Console 的 Appender,也就是输出到控制台。Console 节点中的 PatternLayout 定义了输出日志时的格式:

  • %d{HH:mm:ss.SSS} 表示输出到毫秒的时间
  • %t 输出当前线程名称
  • %-5level 输出日志级别,-5表示左对齐并且固定输出5个字符,如果不足在右边补0
  • %logger 输出 logger 名称,因为 Root Logger 没有名称,所以没有输出
  • %msg 日志文本
  • %n 换行
  • %F 输出所在的类文件名,如 Demo.java
  • %L 输出行号
  • %M 输出所在方法名
  • %l  输出语句所在的行数, 包括类名、方法名、文件名、行数

自定义 Logger 与 Appender

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="OFF">
	<properties>
	    <property name="LOG_HOME">/data/phone-schedule-server/logs/</property>
	    <property name="FILE_NAME">stdout</property>
	    <property name="TRAFFIC_FILE_NAME">traffic</property>
	    <property name="TIME_FILE_NAME">time-log</property>
	</properties>
	<appenders>
	    ...
	    <RollingRandomAccessFile name="stdout" fileName="${LOG_HOME}/${FILE_NAME}.log"
	                             filePattern="${LOG_HOME}/$${date:yyyy-MM}/${FILE_NAME}-%d{yyyy-MM-dd}-%i.log.gz" append="true">
	        <PatternLayout pattern="%date{yyyy-MM-dd HH:mm:ss.SSS} %level [%thread][%file:%line] - %msg%n" />
	        <Policies>
	            <TimeBasedTriggeringPolicy />
	            <SizeBasedTriggeringPolicy size="100 MB" />
	        </Policies>
	        <DefaultRolloverStrategy max="20" />
	    </RollingRandomAccessFile>
	    ...
    </appenders>
    <loggers>

        <logger name="io.netty" level="error"/>
        <logger name="com.baidu.aip" level="error" />

        <logger name="service" level="info" additivity="false">
            <AppenderRef ref = "stdout" />
            <!--<AppenderRef ref="Console" />-->
        </logger>
		...
        
        <root level="info">
            <AppenderRef ref="stdout" />
            <AppenderRef ref="Console" />
        </root>
    </loggers>
</configuration>
实践配置

<properties> 定义了常量方便后面复用

RollingRandomAccessFile 的属性:

  • fileName  指定当前日志文件的位置和文件名称
  • filePattern  指定当发生 Rolling 时,文件的转移和重命名规则
  • SizeBasedTriggeringPolicy  指定当文件体积大于 size 指定的值时,触发 Rolling
  • DefaultRolloverStrategy  指定最多保存的文件个数
  • TimeBasedTriggeringPolicy  这个配置需要和 filePattern 结合使用,注意 filePattern 中配置的文件重命名规则是${FILE_NAME}-%d{yyyy-MM-dd HH-mm}-%i,最小的时间粒度是mm,即分钟,TimeBasedTriggeringPolicy 指定的 size 是1,结合起来就是每一分钟生成一个新文件。如果改成%d{yyyy-MM-dd HH},最小粒度为小时,则每一个小时生成一个文件。

异步配置

Async:异步,需要通过 AppenderRef 来指定要对哪种输出源进行异步(一般用于配置RollingRandomAccessFile)

<Async name="AsyncAppender">
     <AppenderRef ref="RollingRandomAccessFile"/>
</Async>

定义日志输出的地方

Appenders:输出源,用于定义日志输出的地方 log4j2 支持的输出源有很多,有控制台 Console、文件 File、RollingRandomAccessFile、MongoDB、Flume 等

  • Console:控制台输出源是将日志打印到控制台上,开发的时候一般都会配置,以便调试
  • File:文件输出源,用于将日志写入到指定的文件,需要配置输入到哪个位置(例如:D:/logs/mylog.log)
  • RollingRandomAccessFile: 该输出源也是写入到文件,不同的是比 File 更加强大,可以指定当文件达到一定大小(如20MB)时,另起一个文件继续写入日志,另起一个文件就涉及到新文件的名字命名规则,因此需要配置文件命名规则,因为不可能一直往一个文件中写,如果一直写,文件过大,打开就会卡死,也不便于查找日志。
  • NoSql:MongoDb, 输出到 MongDb 数据库中
  • Flume:输出到 Apache Flume,Flume 是 Cloudera提供的一个高可用的,高可靠的,分布式的海量日志采集、聚合和传输的系统,Flume 支持在日志系统中定制各类数据发送方,用于收集数据;同时,Flume 提供对数据进行简单处理,并写到各种数据接受方(可定制)的能力。

升级的过程

由于在项目中使用了百度的语音识别的 Java SDK,在测试的过程中发现有很多 com.baidu.ai 包下 Debug 的日志输入,本以为只要配置了 Log4j2.xml 文件及在 Maven 中引入相应的依赖就可以正常使用了,一直以为出现 Debug 级别的日志在我配置的文件,配置如下:

maven:

<dependency>
    <groupId>com.baidu.aip</groupId>
    <artifactId>java-sdk</artifactId>
    <version>${baiduai.version}</version>
</dependency>

log4j2.xml

<loggers>
    <logger name="io.netty" level="error"/>
    <logger name="com.baidu.aip" level="error" />
</loggers>

后来,仔细看了一下百度的文档,日志使用的 Log4j,所以就顺着思路看了一下 maven 的依赖关系,

然后增加了 exclusions ,如下:

<dependency>
    <groupId>com.baidu.aip</groupId>
    <artifactId>java-sdk</artifactId>
    <version>${baiduai.version}</version>
    <exclusions>
        <exclusion>
            <artifactId>log4j</artifactId>
            <groupId>log4j</groupId>
        </exclusion>
    </exclusions>
</dependency>

然后再测试,结果还是不达预期!

下一步查阅了一下 Lo4j2 的官方文件,找到 Log4j 1.x Migrating 发现:

Perhaps the simplest way to convert to using Log4j 2 is to replace the log4j 1.x jar file with Log4j 2's log4j-1.2-api.jar. However, to use this successfully applications must meet the following requirements: ......

于是,在 maven 的依赖中增加 log4j-1.2-api.jar ,如下:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.6.2</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.6.2</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.6.2</version>
</dependency>

最后,日志的输出也预期一致。