springboot项目logback日志框架分析

1. 说明

Logback是springboot项目中默认的日志框架，通常都是一劳永逸的配置，不需要太多关心。最近的性能优化涉及到将服务升级到webflux这种异步io框架，需要评估日志打印时的性能损耗，需要了解下Logback的实现。

本文主要分析了 解析logback.xml配置文件的主流程、日志打印的占位符解析、异步日志的实现。

2. logback.xml配置文件解析

2.1 加载配置文件

springboot启动时会加载不同的日志实现，具体方法从 org.springframework.boot.logging.AbstractLoggingSystem#loadConfiguration 开始

logback框架加载配置文件：
org.springframework.boot.logging.logback.LogbackLoggingSystem#loadConfiguration

org.springframework.boot.logging.logback.LogbackLoggingSystem#configureByResourceUrl

解析配置文件的类是 ch.qos.logback.classic.joran.JoranConfigurator
在springboot项目中为 SpringBootJoranConfigurator，是JoranConfigurator的实现类

在方法 ch.qos.logback.core.joran.GenericConfigurator#doConfigure 会将xml文件内容解析为 eventList

2.2注册处理规则

配置文件中不同的节点会有对应的解析、处理规则。配置的解析规则被管理在一个容器中，规则容器为： ch.qos.logback.core.joran.spi.SimpleRuleStore

构建interceptor时会调用方法 SpringBootJoranConfigurator#addInstanceRules ，将各个配置元素的解析方法注册至 SimpleRuleStore 中

2.3 处理event

上述已经将配置文件xml的内容解析为eventList，内存里也经注册了每个xml节点对应的处理规则，此处就是遍历eventList，根据不同的解析规则做处理配置内容。

处理event事件的方法是 ch.qos.logback.core.joran.spi.EventPlayer#play ，EventPlayer 类持有上述构建的 interceptor实例。

ch.qos.logback.core.joran.spi.Interpreter#startElement


在执行上述action.begin(interpretationContext, tagName, atts)方法时，会有不同的action的实现

以配置文件中的appender配置为例，会根据appender的全路径名创建对应的实例
ch.qos.logback.core.joran.action.AppenderAction#begin

3. 日志占位符pattern变量解析

Logback通过PatternLayout类解析并处理日志模式（pattern）。Logback的日志模式由一系列的转换器（converters）组成，每个转换器负责处理日志模式中特定的占位符。当Logback遇到一个占位符时，它查找对应的转换器来处理该占位符，然后将转换的结果插入到最终的日志输出中。

如下示例

<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">  
     <encoder>  
        <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} [%X{X-B3-TraceId},%X{X-B3-SpanId}] - %msg%n</pattern>  
    </encoder>
</appender>

示例中的encoder 中定义了实际打印日志的格式，其中通过占位符打印了 日期、线程名等，这些占位符的处理都是依靠 ch.qos.logback.core.pattern.FormattingConverter

在Logback的模式（pattern）中，每个占位符（即转换指令）前都需要加上百分号（%）来标识。
例如：

• %d 表示日期和时间 （参考 DateConverter）

• %thread 表示产生日志事件的线程名（参考 ThreadConverter）

• %level 表示日志级别（如INFO、DEBUG）（参考 LevelConverter）

• %logger 或 %c 表示记录日志的logger名称 （参考 LoggerConverter）

• %mdc或者%X 表示MDC中的变量 （参考 MDCConverter）

• %msg 或 %m 表示日志消息 （参考 MessageConverter）

• %n 表示平台相关的行分隔符，通常是换行符 （参考 LineSeparatorConverter）

  另外可以使用花括号 {} 来为转换指令提供额外的格式选项。例如，%d{yyyy-MM-dd HH:mm:ss} 通过花括号中的格式化字符串定制了日期和时间的输出格式。
  特别地，对于用户的Mapped Diagnostic Context（MDC）数据，使用 %X{key} 来输出MDC中key对应的值

配置中，通过关键字来匹配不同不同的converter，其具体的定义参考：
ch.qos.logback.classic.PatternLayout

打印日志时处理变量的方法为：
ch.qos.logback.core.pattern.PatternLayoutBase#writeLoopOnConverters

4. 日志文件滚动策略 RollingPolicy

RollingPolicy的实现依托于RollingFileAppender。在logback.xml配置文件中，首先配置一个RollingFileAppender，然后在其中指定使用的RollingPolicy。

在Logback中，主要有两种类型的RollingPolicy：

1. TimeBasedRollingPolicy：基于时间的滚动策略。如每天或每小时创建一个新的日志文件。可以通过fileNamePattern进行配置，比如log.%d{yyyy-MM-dd}.txt会每天滚动日志。

2. SizeAndTimeBasedRollingPolicy：基于大小和时间的滚动策略。这不仅会基于时间滚动日志文件，还会基于文件大小（当文件达到一个指定的大小后也会滚动）。例如，可以设置每天滚动日志文件，但如果文件大小超过10MB，也会立即滚动。

5. 异步日志

异步日志的配置示例：

<?xml version="1.0" encoding="UTF-8"?>  
<configuration>  
  
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">  
        <encoder>            
	        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%msg%n</pattern>  
        </encoder>    
	</appender>  
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">         <file>logs/app.log</file>  
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> 
            <fileNamePattern>logs/app-%d{yyyy-MM-dd}.log</fileNamePattern>  
            <maxHistory>30</maxHistory>  
        </rollingPolicy>        
        <encoder>            
	        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>  
        </encoder>    
	</appender>  
    <appender name="ASYNC_CONSOLE" class="ch.qos.logback.classic.AsyncAppender">  
        <appender-ref ref="CONSOLE" />  
        <queueSize>512</queueSize>  
        <discardingThreshold>0</discardingThreshold>  
    </appender>  
  
    <appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">  
        <appender-ref ref="FILE" />  
        <queueSize>512</queueSize>  
        <discardingThreshold>0</discardingThreshold>  
    </appender>  
  
    <root level="INFO">  
        <appender-ref ref="ASYNC_CONSOLE" />  
        <appender-ref ref="ASYNC_FILE" />  
    </root>  
</configuration>

注： 此处的配置实际上是创建了两个 AsyncAppender 对象

打印异步日志的appender是 ch.qos.logback.classic.AsyncAppender ，
其执行的append() 方法为：ch.qos.logback.core.AsyncAppenderBase#append

其中的put() 方法是将当前的日志事件写入队列

此处入队列的行为受到 neverBlock 参数控制（是一个配置项），若 neverBlock=false，则会执行到方法 AsyncAppenderBase#putUninterruptibly，通过循环阻塞式的进行插入，若neverBlock=false 则执行 blockingQueue.offer 方法，但该方法并不保证插入成功，若队列空间不足，会直接抛弃事件。

队列中事件的消费是委托 ch.qos.logback.core.AsyncAppenderBase.Worker 完成

对于 AsyncAppender 而言，只会持有一个 Worker 对象，也就是说，AsyncAppende 的日志虽然是异步打印，但是队列中的log事件是单线程串行打印，是顺序的，不会有乱序的问题。