logback同步配置和异步配置

技术研究
#1

SpringBoot项目logback同步配置和异步配置

logback简介

logback时一个开源的日志组件，springboot自带logback依赖。在项目中使用logback时只需关注配置即可。logback主要分为三个模块：

  1. logback-core，基础模块，其它两个模块的依赖
  2. logback-classic，slfj-api的实现
  3. logback-access，提供HTTP访问Servlet容器（如tomcat）日志的功能

同步日志配置

日志级别

ALL：最低等级的，用于打开所有日志记录

TRACE：很低的日志级别，一般不会使用

DEBUG：指出细粒度信息事件对调试应用程序是非常有帮助的，主要用于开发过程中打印一些运行信息

INFO：消息在粗粒度级别上突出强调应用程序的运行过程。打印一些感兴趣的或者重要的信息，这个可以用于生产环境中输出程序运行的一些重要信息，但是不能滥用，避免打印过多的日志

WARN：表明会出现潜在错误的情形，有些信息不是错误信息，但是也要给出的一些提示

ERROR：指出虽然发生错误事件，但仍然不影响系统的继续运行。打印错误和异常信息，如果不想输出太多的日志，可以使用这个级别

FATAL：指出每个严重的错误事件将会导致应用程序的退出。这个级别比较高了。重大错误，这种级别可以直接停止程序了

OFF：最高等级的，用于关闭所有日志记录。

配置文件命名

配置文件加载顺序

顺序 非SpringBoot项目 SpringBoot项目
1 logback-test.xml ogback-test.xml
2 logback.xml logback.xml
3 application.yml
4 logback-spring.xml

如果配置文件命名为logback.xml，在配置文件中要使用SpringBoot环境中的变量时，就会获取不到。一般来说，建议使用logback-spring.xml。

配置文件结构

<?xml version="1.0" encoding="UTF-8"?>
<!--
scan: 配置文件发生改变时是否重新载入。默认true
scanPeriod: 检测配置是否修改的时间间隔，scan为true时该配置才有效。默认60秒
debug: 是否打印logback内部日志信息。默认false
-->
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <!-- 自定义变量 使用变量方式：${AppName}-->
	<property name="AppName" value="demo"/>
    <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %level [${APP_NAME:-},%X{traceId},%X{spanId},%X{parentId}] ${PID:- } --- [%thread] %-40.40class{39} %L: %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} \n"/>
    <!-- 上下文名称 默认default -->
    <contextName>default</contextName>
    <!-- 定义日志追加器-->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <!-- 过滤器 -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>debug</level>
        </filter>
		<!-- 输出格式
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <!-- 设置字符集 -->
            <charset>UTF-8</charset>
        </encoder>
    </appender>
	
	
	<root level="debug">
		<appender-ref ref="CONSOLE"/>
	</root>

    <logger name="com.szkingdom" level="DEBUG">
        <appender-ref ref="CONSOLE"/>
	</logger>

</configuration>

appender

name:追加器名称
class:追加器所在路径。可以是logback提供的追加器，如ConsoleAppender、FileAppender
RollingFileAppender，也可以是自定义的追加器

  1. ConsoleAppender

    <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %level [${APP_NAME:-},%X{traceId},%X{spanId},%X{parentId}] ${PID:- } --- [%thread] %-40.40class{39} %L: %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} \n"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
  <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>debug</level>
  </filter>
  <encoder>
    <Pattern>${LOG_PATTERN}</Pattern>
    <!-- 设置字符集 -->
    <charset>UTF-8</charset>
  </encoder>
</appender>

  2. RollingFileAppender

    <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %level [${APP_NAME:-},%X{traceId},%X{spanId},%X{parentId}] ${PID:- } --- [%thread] %-40.40class{39} %L: %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} \n"/>
<property name="LOG_FILE" value="${BUILD_FOLDER:-logs}/${APP_NAME}"/>
<appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_FILE}/log_debug.log</file>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
        <charset>UTF-8</charset>
    </encoder>
    <!-- 日志记录器的滚动策略-->
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <!-- rollover daily -->
        <fileNamePattern>${LOG_FILE}/debug/log-debug-%d{yyyy-MM-dd_HH-mm}.%i.log</fileNamePattern>
        <!-- each file should be at most 100MB, keep 60 days worth of history, but at most 20GB -->
        <!--单个日志文件最大100M，到了这个值，就会再创建一个日志文件，日志文件的名字最后+1-->
        <maxFileSize>100MB</maxFileSize>
        <!--日志文件保留天数-->
        <maxHistory>30</maxHistory>
        <!--所有的日志文件最大20G，超过就会删除旧的日志-->
        <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>debug</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
</appender>

filter

满足条件的日志才会被记录，logback默认已经提供多种过滤，也可以自己定义过滤器。详情见过滤器

encoder

通过pattern指定日志格式，charset指定字符集

%d表示时间

%thread表示线程名

%-5level 表示日志级别，允许以五个字符长度输出

%logger{50}表示具体的日志输出者，比如类名，括号内表示长度

%msg表示具体的日志消息，就是logger.info(“xxx”)中的xxx %n表示换行

root

通过appender-ref指定启用的appender。

root的属性level是对启动的所有appender的日志级别控制，实际输出的日志会取root和appender最大日志级别。

logger

包或类日志配置

name: 类路径或者包路径

level:日志级别

additivity:是否向上级传递日志，默认true

异步日志配置

logback使用AsyncAppender来异步记录日志，实际上只是将要打印、写入文件或写入数据库的日志保存到队列中，最终还是调用ConsoleAppender、RollingFileAppdender来处理日志。

为什么要异步输出日志

输出日志和业务逻辑在同一个线程，有日志输出时，必须等待日志出输出完成后才会执行业务逻辑的代码，在高并发的场景下，大量的日志输出操作会使线程卡顿在输出日志的过程中，降低程序性能。

配置

以异步输出滚动日志文件为例

<property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %level [${APP_NAME:-},%X{traceId},%X{spanId},%X{parentId}] ${PID:- } --- [%thread] %-40.40class{39} %L: %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} \n"/>
<property name="LOG_FILE" value="${BUILD_FOLDER:-logs}/${APP_NAME}"/>
<appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_FILE}/log_debug.log</file>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
        <charset>UTF-8</charset>
    </encoder>
    <!-- 日志记录器的滚动策略-->
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <!-- rollover daily -->
        <fileNamePattern>${LOG_FILE}/debug/log-debug-%d{yyyy-MM-dd_HH-mm}.%i.log</fileNamePattern>
        <!-- each file should be at most 100MB, keep 60 days worth of history, but at most 20GB -->
        <!--单个日志文件最大100M，到了这个值，就会再创建一个日志文件，日志文件的名字最后+1-->
        <maxFileSize>100MB</maxFileSize>
        <!--日志文件保留天数-->
        <maxHistory>30</maxHistory>
        <!--所有的日志文件最大20G，超过就会删除旧的日志-->
        <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>debug</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
</appender>
<appender name ="ASYNC_DEBUG_FILE" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="DEBUG_FILE"/>
</appender>
  1. discardingThreshold，丢弃策略执行的阈值，如果队列剩余小于这个阈值且当前日志 level TRACE, DEBUG or INFO时，会丢弃这些日志。如果为0时，表示不会丢弃日志，队列满了会进行阻塞。默认20
  2. queueSize，队列大小，默认256
  3. neverBlock，永不阻塞，如果队列满了则直接返回

异步配置案例

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>
<configuration scan="true">
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />

    <!-- 应用名称 -->
    <springProperty scope="context" name="APP_NAME" source="spring.application.name"/>
    <!-- 日志编码 -->
    <property name="ENCODING" value="UTF-8"/>
    <!-- 日志文件路径 -->
    <property name="LOG_PATH" value="${BUILD_FOLDER:-logs}/${APP_NAME}"/>
    <!-- DEBUG日志文件归档路径 -->
    <property name="DEBUG_LOG_PATH" value="${LOG_PATH}/debug/${APP_NAME}"/>
    <!-- INFO日志文件归档路径 -->
    <property name="INFO_LOG_PATH" value="${LOG_PATH}/info/${APP_NAME}"/>
    <!-- WARN日志文件归档路径 -->
    <property name="WARN_LOG_PATH" value="${LOG_PATH}/warn/${APP_NAME}"/>
    <!-- ERROR日志文件归档路径 -->
    <property name="ERROR_LOG_PATH" value="${LOG_PATH}/error/${APP_NAME}"/>
    <!-- brave-tracer日志文件归档路径 -->
    <property name="BRAVE_TRACER_LOG_PATH" value="${LOG_PATH}/brave-tracer/${APP_NAME}"/>
    <property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %level [${APP_NAME:-},%X{traceId},%X{spanId},%X{parentId}] ${PID:- } --- [%thread] %-40.40class{39} %L: %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx} \n"/>

    <!-- 统一控制台输出日志 -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>${ENCODING}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
    </appender>

    <!-- 统一DEBUG日志输出 -->
    <appender name="debug_file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}-debug.log</file>
        <!-- 日志归档 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${DEBUG_LOG_PATH}-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <Pattern>${LOG_PATTERN}</Pattern>
            <charset>${ENCODING}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>DEBUG</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <!-- 统一INFO日志输出 -->
    <appender name="info_file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}-info.log</file>
        <!-- 日志归档 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${INFO_LOG_PATH}-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <Pattern>${LOG_PATTERN}</Pattern>
            <charset>${ENCODING}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <!-- 统一WARN日志输出 -->
    <appender name="warn_file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}-warn.log</file>
        <!-- 日志归档 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${WARN_LOG_PATH}-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <Pattern>${LOG_PATTERN}</Pattern>
            <charset>${ENCODING}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <!-- 统一ERROR日志输出 -->
    <appender name="error_file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}-error.log</file>
        <!-- 日志归档 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${ERROR_LOG_PATH}-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <Pattern>${LOG_PATTERN}</Pattern>
            <charset>${ENCODING}</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <appender name="brave_tracer_file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_FILE}.trace.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${BRAVE_TRACER_LOG_PATH}-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <Pattern>%msg%n</Pattern>
            <charset>${ENCODING}</charset>
        </encoder>
    </appender>

    <appender name ="async_debug_file" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="debug_file"/>
    </appender>

    <appender name ="async_info_file" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="info_file"/>
    </appender>

    <appender name ="async_warn_file" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="warn_file"/>
    </appender>

    <appender name ="async_error_file" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="error_file"/>
    </appender>

    <appender name ="async_brave_tracer_file" class= "ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>20</discardingThreshold>
        <queueSize>256</queueSize>
        <neverBlock>false</neverBlock>
        <appender-ref ref ="brave_tracer_file"/>
    </appender>

    <root level="info">
        <appender-ref ref="console"/>
        <appender-ref ref="async_debug_file"/>
        <appender-ref ref="async_info_file"/>
        <appender-ref ref="async_warn_file"/>
        <appender-ref ref="async_error_file"/>
    </root>

    <!--该logger会继承root的appender -->
    <logger name="com.szkingdom" level="info"/>

    <logger name="brave.Tracer" level="INFO" additivity="false">
        <appender-ref ref="async_brave_tracer_file"/>
    </logger>
</configuration>

性能对比

测试的日志框架

  1. logback1.2.9同步日志
  2. logback1.2.9异步日志
  3. logback1.3.7异步日志
  4. logback1.3.7异步日志
  5. log4j2.18.0同步日志
  6. log4j2.18.0异步日志

测试环境

         		      JDK: azul-1.8.0_372
         Operating System: Windows 10 家庭中文版 64-bit (10.0, Build 19045) (19041.vb_release.191206-1406)
                 Language: Chinese (Simplified) (Regional Setting: Chinese (Simplified))
      System Manufacturer: ASUSTeK COMPUTER INC.
             System Model: X542UQR
                     BIOS: X542UQR.309 (type: UEFI)
                Processor: Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz (8 CPUs), ~2.0GHz
                   Memory: 16384MB RAM
      Available OS Memory: 16270MB RAM
                Page File: 21427MB used, 8659MB available

测试工具

jmh1.09

参数：-f 1 -tu ms -wi 2 -i 5 -t {1,2,4,16,32,64}

测试结果

Threads logback1.2.9 Async logback1.2.9 Sync logback1.3.7 Async logback1.3.7 Sync log4j2.18.0 Async log4j2.18.0 Sync Unit
1 357.728 389.144 370.710 360.961 233.370 390.871 ops/ms
2 347.908 393.659 373.666 352.226 257.216 397.496 ops/ms
4 241.653 375.129 371.660 338.377 254.090 406.206 ops/ms
8 151.541 379.731 370.519 356.223 253.066 401.591 ops/ms
16 124.349 332.613 370.471 366.478 250.208 401.789 ops/ms
32 118.019 310.043 370.132 360.580 248.227 359.671 ops/ms
64 111.478 330.585 368.876 359.243 249.226 365.272 ops/ms