Logback文件这么配置，TPS提高至少10倍

来源：https://tinyurl.com/y5zbtgsq

阅读本文，你将了解到

• 日志输出到文件并根据LEVEL级别将日志分类保存到不同文件
• 通过异步输出日志减少磁盘IO提高性能
• 异步输出日志的原理

配置文件logback-spring.xml

SpringBoot工程自带logback和slf4j的依赖，所以重点放在编写配置文件上，需要引入什么依赖，日志依赖冲突统统都不需要我们管了。

logback框架会默认加载classpath下命名为logback-spring或logback的配置文件。将所有日志都存储在一个文件中文件大小也随着应用的运行越来越大并且不好排查问题，正确的做法应该是将error日志和其他日志分开，并且不同级别的日志根据时间段进行记录存储。

 

标签说明

• <root>标签，必填标签，用来指定最基础的日志输出级别
• <appender-ref>标签，添加append
• <appender>标签，通过使用该标签指定日志的收集策略
• name属性指定appender命名
• class属性指定输出策略，通常有两种，控制台输出和文件输出，文件输出就是将日志进行一个持久化。ConsoleAppender将日志输出到控制台
• <filter>标签，通过使用该标签指定过滤策略
• <level>标签指定过滤的类型
• <encoder>标签，使用该标签下的标签指定日志输出格式
• <pattern>标签指定日志输出格式
• <rollingPolicy>标签指定收集策略，比如基于时间进行收集
• <fileNamePattern>标签指定生成日志保存地址，通过这样配置已经实现了分类分天手机日志的目标了

 

logback 高级特性异步输出日志

之前的日志配置方式是基于同步的，每次日志输出到文件都会进行一次磁盘IO。采用异步写日志的方式而不让此次写日志发生磁盘IO，阻塞线程从而造成不必要的性能损耗。异步输出日志的方式很简单，添加一个基于异步写日志的 appender，并指向原先配置的 appender即可

 

异步输出日志性能测试

既然能提高性能的话，必须进行一次测试比对，同步和异步输出日志性能到底能提升多少倍？

服务器硬件

• CPU 六核
• 内存 8G

测试工具

• Apache Jmeter

同步输出日志

• 线程数：100
• Ramp-Up Loop(可以理解为启动线程所用时间) ：0
• 可以理解为100个线程同时启用

测试结果

 

重点关注指标Throughput【TPS】吞吐量：系统在单位时间内处理请求的数量，在同步输出日志中TPS为44.2/sec

异步输出日志

• 线程数 100
• Ramp-Up Loop：0

测试结果

 

TPS为497.5/sec，性能提升了10多倍！！！

异步日志输出原理

从logback框架下的Logger.info方法开始追踪。一路的方法调用路径如下图所示：

 

异步输出日志中最关键的就是配置文件中ch.qos.logback.classic包下AsyncAppenderBase类中的append方法，查看该方法的源码:

 

通过队列情况判断是否需要丢弃日志，不丢弃的话将它放到阻塞队列中，通过查看代码，这个阻塞队列为ArrayBlockingQueueu，默认大小为256，可以通过配置文件进行修改。

Logger.info(…)到append(…)就结束了，只做了将日志塞入到阻塞队列的事，然后继续执行Logger.info(…)下面的语句了。

在AsyncAppenderBase类中定义了一个Worker线程，run方法中的关键部分代码如下:

 

从阻塞队列中取出一个日志，并调用 AppenderAttachableImpl类中的 appendLoopOnAppenders方法维护一个 Append列表。Worker线程中调用方法过程主要如下图：

 

最主要的两个方法就是encode和write方法，前一个法方会根据配置文件中encode指定的方式转化为字节码，后一个方法将转化成的字节码写入到文件中去。所以写文件是通过新起一个线程去完成的，主线程将日志扔到阻塞队列中，然后又去做其他事情了。

实例：

<?xml version="1.0" encoding="UTF-8"?>

<!-- 日志级别从低到高分为TRACE < DEBUG < INFO < WARN < ERROR < FATAL，如果设置为WARN，则低于WARN的信息都不会输出 -->
<!-- scan:当此属性设置为true时，配置文件如果发生改变，将会被重新加载，默认值为true -->
<!-- scanPeriod:设置监测配置文件是否有修改的时间间隔，如果没有给出时间单位，默认单位是毫秒。当scan为true时，此属性生效。默认的时间间隔为1分钟。 -->
<!-- debug:当此属性设置为true时，将打印出logback内部日志信息，实时查看logback运行状态。默认值为false。 -->
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <!--windows日志文件存储路径,勿在 LogBack 的配置中使用相对路径-->
    <property name="LOG_HOME" value="${user.dir}/logs/"/>
    <!--mac日志文件存储路径-->
    <!--<property name="LOG_HOME" value="/Users/macbook/Documents/logs"/>-->
    <!-- 组件标识 -->
    <property name="COMPONENT_ID" value="iDataFusion"/>
    <!-- 段标识 -->
    <property name="SEGMENT_ID" value="custominterface-base"/>

    <logger name="org.springframework.scheduling">
        <level value="info"/>
    </logger>

    <!-- 控制台输出日志 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <!--<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}[%line] - %msg%n</pattern>-->
            <pattern>%red(%d{yyyy-MM-dd HH:mm:ss.SSS}) %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{50})[%line] - %cyan(%msg%n)
            </pattern>
        </layout>
    </appender>

    <appender name="FILE-error" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!--此日志appender是为开发使用，只配置最底级别，控制台输出的日志级别是大于或等于此级别的日志信息-->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <File>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.error.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.error.%d{yyyy-MM-dd}.%i.log.zip</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>3</MaxHistory>
            <!--日志文件最大的大小-->
            <maxFileSize>25MB</maxFileSize>
            <!-- 所有归档文件的总大小 -->
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %level ${COMPONENT_ID}.${SEGMENT_ID} [%thread] [%logger{50}:%line] %msg%n
            </Pattern>
        </layout>
    </appender>

    <appender name="FILE-warn" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <File>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.warn.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.warn.%d{yyyy-MM-dd}.%i.log.zip</FileNamePattern>
            <MaxHistory>3</MaxHistory>
            <maxFileSize>25MB</maxFileSize>
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %level ${COMPONENT_ID}.${SEGMENT_ID} [%thread] [%logger{50}:%line] - %msg%n
            </Pattern>
        </layout>
    </appender>

    <appender name="FILE-info" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <File>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.info.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.info.%d{yyyy-MM-dd}.%i.log.zip</FileNamePattern>
            <MaxHistory>3</MaxHistory>
            <maxFileSize>25MB</maxFileSize>
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %level ${COMPONENT_ID}.${SEGMENT_ID} [%thread] [%logger{50}:%line] - %msg%n
            </Pattern>
        </layout>
    </appender>

    <!-- 文件输出日志 (文件大小策略进行文件输出，超过指定大小对文件备份)-->
    <appender name="FILE-debug" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>DEBUG</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <File>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.debug.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/${COMPONENT_ID}.${SEGMENT_ID}.debug.%d{yyyy-MM-dd}.%i.log.zip</FileNamePattern>
            <MaxHistory>3</MaxHistory>
            <maxFileSize>25MB</maxFileSize>
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %level ${COMPONENT_ID}.${SEGMENT_ID} [%thread] [%logger{50}:%line] - %msg%n
            </Pattern>
        </layout>
    </appender>

    <logger name="org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping" level="off"/>
    <logger name="springfox.documentation.schema.ModelContextKeyGenerator" level="off"/>
    <logger name="springfox.documentation.spring.web.caching.CachingAspect" level="off"/>
    <logger name="springfox.documentation.spring.web.OperationsKeyGenerator" level="off"/>
    <logger name="springfox.documentation.spring.web.scanners.ApiListingReferenceScanner" level="off"/>
    <logger name="springfox.documentation.schema.property.ModelPropertiesKeyGenerator" level="off"/>
    <logger name="springfox.documentation.schema.property.BeanPostProcessorChecker" level="off"/>

    <!--swagger2官方介绍的bug-->
    <logger name="io.swagger.models.parameters.AbstractSerializableParameter">
        <level value="ERROR"/>
    </logger>

    <!-- 日志输出级别 -->
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE-debug"/>
        <appender-ref ref="FILE-info"/>
        <appender-ref ref="FILE-warn"/>
        <appender-ref ref="FILE-error"/>
    </root>

</configuration>