本文旨在阐述日志框架使用配置和记录时需要注意的点。

概述

Java 体系中有众多的日志框架，包括Logback、Log4j、Log4j2、commons-logging、JDK 自带的 java.util.logging 等。

为了做日志的统一管理，就有了 SLF4J（Simple Logging Facade For Java）。

SL4J 实现了三种功能：

  1. 统一 API。SL4J 提供了统一的日志门面的API。
  2. 桥接功能。提供 API 把各种日志框架的 API 桥接到 SL4J 的 API 上。
  3. 适配功能。SLF4J 只是日志标准，还需要一个实际的日志框架。日志框架本身没有实现 SLF4J API，所以需要有一个前置转换。因此，SL4J 提供了 API ,可以实现 SLF4J API 和实际日志框架的绑定。Logback 就是按照 SLF4J API 标准实现的，因此不需要绑定模块做转换。


注：虽然可以使用 log4j-over-slf4j 来实现 Log4j 桥接到 SLF4J，也可以使用 slf4j-log4j12 实现 SLF4J 适配到 Log4j，也把它们画到了一列，但是它不能同时使用它们，否则就会产生死循环。jcl 和 jul 也是同样的道理。

查看日志框架的依赖关系

使用mvn dependency:tree命令可以查看一个maven工程的依赖关系。如，查看springboot工程的依赖关系，可以看到springboot中默认引入的日志框架中，log4j-to-slf4j 用于实现 Log4j2 API 到 SLF4J 的桥接，jul-to-slf4j 则是实现 java.util.logging API 到 SLF4J 的桥接。

1
2
3
4
5
6
+- org.springframework.boot:spring-boot-starter-logging:jar:2.2.1.RELEASE:compile
|  +- ch.qos.logback:logback-classic:jar:1.2.3:compile
|  |  \- ch.qos.logback:logback-core:jar:1.2.3:compile
|  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.12.1:compile
|  |  \- org.apache.logging.log4j:log4j-api:jar:2.12.1:compile
|  \- org.slf4j:jul-to-slf4j:jar:1.7.29:compile

日志配置

问题一：重复记录

错误配置 logger 的继承关系

场景

在 logger 中，配置了控制台的继承，导致在控制台输出了两次日志。这是由于同一条日志既会通过 logger 记录，也会发送到 root 记录。

1
2
3
4
5
6
7
8
9
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    ...
</appender>
<logger name="{applicationpath}" level="DEBUG">
    <appender-ref ref="CONSOLE"/>
</logger>
<root level="INFO">
    <appender-ref ref="CONSOLE"/>
</root>

解决方式

  1. 去掉 logger中的继承关系。

    1
    <logger name="{applicationpath}" level="DEBUG"/>

  2. 如果自定义的需要把日志输出到不同的 Appender，比如将应用的日志输出到文件 app.log、把其他框架的日志输出到控制台，可以设置的 additivity 属性为 false，这样就不会继承别的 Appender 了。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
            <file>app.log</file>
            ...
        </appender>
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    		...
    	</appender>
        <logger name="{applicationpath}" level="DEBUG" additivity="false">
            <appender-ref ref="FILE"/>
        </logger>
    	<root level="INFO">
    		<appender-ref ref="CONSOLE" />
    	</root>
    </appender>

错误配置 LevelFilter

场景

定义 appender，想要输出 info 文件只记录 info 级别的日志，输出 error 文件记录 warn、error 级别的日志。由于对 LevelFilter 的错误使用，导致在 info 文件里也输出了 warn 和 error 级别的日志。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
		<File>${logDir}/${app.name}_info.log</File>
		<filter class="ch.qos.logback.classic.filter.LevelFilter">
			<level>INFO</level>
		</filter>
	    ...
</appender>
<appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender">
	<File>${logDir}/${app.name}_error.log</File>
	<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
		<level>WARN</level>
	</filter>
	...
</appender>

分析

ThresholdFilter 的作用：记录大于等于配置等级的日志。

LevelFilter 的作用：比较日志级别，做相应处理。如果匹配到配置的等级就交给 onMatch 处理，否则就 交给 onMismatch 处理，默认交给下一个过滤器处理。

在 LevelFilter 中，由于没有配置 onMatch 和 onMismatch 属性，所以相当于这个过滤器是无用的，导致 INFO 以上级别的日志都记录了。

解决方式

配置 LevelFilter 的 onMatch 属性为 ACCEPT，表示接收 INFO 级别的日志；配置 onMismatch 属性为 DENY，表示除了 INFO 级别都不记录。

1
2
3
4
5
6
7
8
9
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
  <File>${logDir}/${app.name}_info.log</File>
  <filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>INFO</level>
    <onMatch>ACCEPT</onMatch>
    <onMismatch>DENY</onMismatch>
  </filter>
  ...
</appender>

问题二：异步日志的性能问题

概述

场景：日志框架在记录日志时，采用的是同步记录。因此，当有大量日志写入时，会影响业务逻辑执行耗时和吞吐量。

解决方式：使用 Logback 提供的 AsyncAppender 即可实现异步的日志记录。定义一个异步 Appender ASYNCFILE，包装之前的同步文件日志记录的 FileAppender，就可以实现异步记录日志到文件。

1
2
3
4
5
6
7
8
...
<appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE"/>
</appender>
<root level="INFO">
    <appender-ref ref="ASYNCFILE"/>
    <appender-ref ref="CONSOLE"/>
</root>

AsyncAppender 异步日志

场景

AsyncAppender 异步日志使用时可能出现的问题有：

  • 记录异步日志撑爆内存；
  • 记录异步日志出现日志丢失；
  • 记录异步日志出现阻塞。

原因：AsyncAppender 的参数配置有误。

分析

AsyncAppender 提供了一些参数配置：

  • includeCallerData：用于控制是否收集调用方数据，默认是 false，此时方法行号、方法名等信息将不能显示。
  • queueSize：用于控制阻塞队列大小，使用的 ArrayBlockingQueue 阻塞队列，默认大小是 256，即内存中最多保存 256 条日志。
  • discardingThreshold：控制丢弃日志的阈值，主要是防止队列满后阻塞。默认情况下，队列剩余量低于队列长度的 20%，就会丢弃 TRACE、DEBUG 和 INFO 级别的日志。
  • neverBlock：用于控制队列满的时候，加入的数据是否直接丢弃，不会阻塞等待，默认是 false。

参数配置不合理可能造成的影响：

  • queueSize配置太大：OOM。
  • queueSize配置太小，且 discardingThreshold配置大于0（或者均为默认值）：队列剩余容量少于 discardingThreshold 的配置就会丢弃 <=INFO 的日志。
  • neverBlock 默认为 false：意味着总可能会出现阻塞。如果 discardingThreshold 为 0，那么队列满时再有日志写入就会阻塞；如果 discardingThreshold 不为 0，也只会丢弃 <=INFO 级别的日志，那么出现大量错误日志时，还是会阻塞程序。

解决方式

根据性能优先，还是数据不丢优先，来配置参数：

  • 如果考虑绝对性能为先，那就设置 neverBlock 为 true，永不阻塞。
  • 如果考虑绝对不丢数据为先，那就设置 discardingThreshold 为 0，即使是 <=INFO 的级别日志也不会丢，但最好把 queueSize 设置大一点，毕竟默认的 queueSize 显然太小，太容易阻塞。
  • 如果希望兼顾两者，可以丢弃不重要的日志，把 queueSize 设置大一点，再设置一个合理的 discardingThreshold。

日志记录

注意

  • 使用{}占位符语法不能通过延迟参数值获取，来解决日志数据获取的性能问题。

    1
    log.debug("debug:{}", delay_onesecond("debug2"));

  • 可以使用 Log4j2 的 API，利用其 lamda 表达式，让参数延迟到真正需要记录日志时再获取，提高读取性能。

    1
    log.debug("debug:{}", ()->delay_onesecond("debug"));

结论

日志框架提供的参数化日志记录方式不能完全取代日志级别的判断。如果日志量很大，获取日志参数代价也很大，就要进行相应日志级别的判断，避免不记录日志也要花费时间获取日志参数的问题。

还有点啥

  • EvaluatorFilter（求值过滤器），用于判断日志是否符合某个条件。配合使用标记和 EvaluatorFilter，可以实现日志的按标签过滤。比如，可以给输出测试结果的那条日志上做 time 标记。
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            ...
            <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
                <evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
                    <marker>time</marker>
                </evaluator>
                <onMismatch>DENY</onMismatch>
                <onMatch>ACCEPT</onMatch>
            </filter>
        </appender>

参考