【日志打印】Log4j

阿里技术针对Java日志的专题系列： https://new.qq.com/rain/a/20240522A010GS00

Log4j2中RollingFile的文件滚动更新机制：https://www.cnblogs.com/yeyang/p/7944899.html

日志搞不定？手把手教你如何使用Log4j2  https://open.alipay.com/portal/forum/post/137701054?ant_source=opendoc_recommend

日志打印实战（含同步、异步、内部实现原理图）：https://www.cnblogs.com/yeyang/p/7944906.html

 异步日志：性能优化的金钥匙   https://new.qq.com/rain/a/20240704A0122F00

 

Log4j2的结构：

  • Logger: 这是开发者直接使用的接口，用于记录不同级别的日志信息（如DEBUG, INFO, ERROR等）。每个Logger都有一个名称，并且支持继承性，形成一个名为Logger Hierarchy的树状结构，根Logger的名称为"root"。
  • LoggerContext: 是日志系统的上下文环境，管理着一组Logger实例以及它们的配置。每个应用程序通常只有一个LoggerContext，但它支持多个上下文以实现更细粒度的控制。
  • Configuration: 每个LoggerContext都关联一个有效的Configuration，定义了日志的输出目的地（Appenders）、日志的过滤规则（Filters）、日志的格式化方式（Layouts）等。Configuration可以通过配置文件（如XML、JSON、properties）或编程方式动态加载。
  • Appender: 负责将日志事件发送到指定的目标，如控制台（Console）、文件（File）、数据库、网络Socket等。
  • Layout: 定义了日志信息的格式化方式，如模式字符串（Pattern String）决定了日期、时间、日志级别、线程名、日志信息等内容的排列和格式。
  • Filter: 可以在日志事件从Logger传递到Appender的过程中进行过滤，根据特定条件决定日志是否被输出。
  • Lookup: 提供动态值解析机制，如${ctx:variable}可以在日志中插入上下文变量的值。

log4j2.xml配置文件组成：

<Configuration>
    <Properties>
    </Properties>

    <appenders>    
    </appenders>
    
    <loggers>
    </loggers>
<Configuration>

一、<appenders>

RollingFileAppender日志绕接

 RollingFileAppender是Log4j2中的一种能够实现日志文件滚动更新(rollover)的Appender。

rollover的意思是当满足一定条件(如文件达到了指定的大小，达到了指定的时间)后，就重命名原日志文件进行归档，并生成新的日志文件用于log写入。如果还设置了一定时间内允许归档的日志文件的最大数量，将对过旧的日志文件进行删除操作。

 RollingFile实现日志文件滚动更新，依赖于TriggeringPolicy和RolloverStrategy。
  • TriggeringPolicy为触发策略，其决定了何时触发日志文件的rollover，即When。
  • RolloverStrategy为滚动更新策略，其决定了当触发了日志文件的rollover时，如何进行文件的rollover，即How。

TriggeringPolicy  触发策略

定义：<Policies></Policies>

RollingFile的触发rollover的策略有：

  • CronTriggeringPolicy(Cron表达式触发)
  • OnStartupTriggeringPolicy(JVM启动时触发)
  • SizeBasedTriggeringPolicy(基于文件大小)：size参数可以用KB、MB、GB等做后缀来指定具体的字节数，如20MB。

  • TimeBasedTriggeringPolicy规定了当日志文件名中的date/time pattern不再符合filePattern中的date/time pattern时，触发rollover操作。

    比如，filePattern指定文件重命名规则为app-%d{yyyy-MM-dd HH}.log，文件名为app-2017-08-25 11.log，当时间达到2017年8月25日中午12点（2017-08-25 12），将触发rollover操作。

参数1：interval
integer型，指定两次封存动作之间的时间间隔。这个配置需要和filePattern结合使用，filePattern日期格式精确到哪一位，interval也精确到哪一个单位。注意filePattern中配置的文件重命名规则是%d{yyyy-MM-dd HH-mm-ss}-%i，最小的时间粒度是ss，即秒钟。
TimeBasedTriggeringPolicy默认的size是1，结合起来就是每1秒钟生成一个新文件。如果改成%d{yyyy-MM-dd HH}，最小粒度为小时，则每一个小时生成一个文件

参数2：modulate
boolean型，说明是否对封存时间进行调制。若modulate=true， 则封存时间将以0点为边界进行偏移计算。比如，modulate=true，interval=4hours， 那么假设上次封存日志的时间为03:00，则下次封存日志的时间为04:00， 之后的封存时间依次为08:00，12:00，16:00
  • CompositeTriggeringPolicy(多个触发策略的混合，如同时基于文件大小和时间)：将多个TriggeringPolicy放到Policies中表示使用复合策略，有一个条件满足即可

DefaultRolloverStrategy滚动更新策略

　　DefaultRolloverStrategy是Log4j2提供的默认的rollover策略，即使在log4j2.xml中没有显式指明，也相当于为RollingFile配置下添加了如下语句。DefaultRolloverStrategy默认的max为7

　　1.2.1 DeleteAction

　　　　DefaultRolloverStrategy制定了默认的rollover策略，通过max参数可控制一定时间范围内归档的日志文件的最大个数。

　　　　Log4j 2.5 引入了DeleteAction，使用户可以自己控制删除哪些文件，而不仅仅是通过DefaultRolloverStrategy的默认策略。

 二、<Loggers>

常见2种：Root 和具体Logger

2.1 Root：

　　指定项目的根日志，如果没有单独指定logger，则默认使用Root输出；每个日志比如配置一个根Root，没有name属性，不需配置additivity属性

2.2 Logger

　　单独指定日志的形式，属性：

　　name： 指定该Logger所适用的类或所在包路径，继承自Root节点

　　level：   日志输出级别，未指定默认ERROR

　　AppenderRef： 指定该日志输出到哪个Appender，如果没指定，默认继承自Root。如果指定则会在指定Appender和Root的Appender都输出。

　　可以配置1个或多个AppenderRef属性。可以设置 additivity = "false"（默认true） 只在自定义的Appender进行输出

三、其他

MDC工具类

　　MDC: Mapped Diagnostic Context，可以粗略的理解成是一个线程安全的存放诊断日志的容器。内部通过ThreadLocal实现了不同线程的隔离。

　　参考：https://www.jianshu.com/p/8b01d62e2431　https://juejin.cn/post/6844904132478763022

       内部实现：依赖MDCAdapter接口，不同的日志组件都实现如Log4jMDCAdapter

　　应用场景：

　　　　a）WEB应用，如果想在日志中输出请求用户IP 地址、请求 URL、统计耗时等等；
　　　　b）在WEB应用中，借助MDC来保存用户请求时产生的reqId，当请求完成后，再将reqId进行移除，这么通过grep reqId就能轻松get整个请求流程的日志轨迹；
　　　　c）在微服务盛行的当下，链路跟踪是个难题，而借助MDC去埋点

　　Seata代码

　　　　 

　　MDC API:

　　　　

　　代码样例：需代码和log*.xml配合使用

　　　  

　　效果：

　　　　

      　　多线程场景验证：

　　　　

 

ThresholdFilter配置：onMatch表示匹配设定的日志级别后是DENY还是ACCEPT，onMismatch表示不匹配设定的日志级别是DENY还是ACCEPT还是NEUTRAL

match/misMatch指的是高于或等于设定的日志级别。所以，要先定义日志级别高的Filter。

onMatch和onMismatch都有三个属性值，分别为Accept、DENY和NEUTRAL

介绍一下这两个配置项的三个属性值：

    • onMatch="ACCEPT" 表示匹配该级别及以上
    • onMatch="DENY" 表示不匹配该级别及以上
    • onMatch="NEUTRAL" 表示该级别及以上的，由下一个filter处理，如果当前是最后一个，则表示匹配该级别及以上
    • onMismatch="ACCEPT" 表示匹配该级别以下
    • onMismatch="NEUTRAL" 表示该级别及以下的，由下一个filter处理，如果当前是最后一个，则不匹配该级别以下的
    • onMismatch="DENY" 表示不匹配该级别以下的

<ThresholdFilter level="FATAL" onMatch="DENY" onMismatch="NEUTRAL"/>
<ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
<ThresholdFilter level="WARN" onMatch="DENY" onMismatch="NEUTRAL"/>
只打印INFO和ERROR

异步日志

使用log4j2的同步日志进行日志输出，日志输出语句与程序的业务逻辑语句将在同一个线程运行，

使用异步日志进行输出时，日志输出语句与业务逻辑语句并不是在同一个线程中运行，而是有专门的线程用于进行日志输出操作，处理业务逻辑的主线程不用等待即可执行后续业务逻辑。

Log4j2中的异步日志实现方式有AsyncAppender和AsyncLogger两种。

  • AsyncAppender采用了ArrayBlockingQueue来保存需要异步输出的日志事件；
  • AsyncLogger则使用了Disruptor框架来实现高吞吐。

AsyncAppender

每个Async Appender，内部维护了一个ArrayBlockingQueue，并将创建一个线程用于输出日志事件，如果配置了多个AppenderRef，将分别使用对应的Appender进行日志输出。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
  <Appenders>
    <RollingFile name="MyFile" fileName="logs/app.log">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
      </PatternLayout>
      <SizeBasedTriggeringPolicy size="500MB"/>
    </RollingFile>
    <Async name="Async">
      <AppenderRef ref="MyFile"/>
    </Async>
  </Appenders>
  <Loggers>
    <Root level="error">
      <AppenderRef ref="Async"/>
    </Root>
  </Loggers>
</Configuration>

AsyncLogger（推荐）

内部使用了Disruptor框架。基于Disruptor开发的系统单线程能支撑每秒600万订单。

Disruptor框架内部核心数据结构为RingBuffer，其为无锁环形队列。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="MyApp" packages="">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        </Console>
        <RollingFile name="RollingFile" fileName="logs/app.log"
                     filePattern="logs/app-%d{yyyy-MM-dd HH}.log">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB"/>
            </Policies>
        </RollingFile>
        <RollingFile name="RollingFile2" fileName="logs/app2.log"
                     filePattern="logs/app2-%d{yyyy-MM-dd HH}.log">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="500MB"/>
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <AsyncLogger name="com.meituan.Main" level="trace" additivity="false">
            <appender-ref ref="RollingFile"/>
        </AsyncLogger>
        <AsyncLogger name="RollingFile2" level="trace" additivity="false">
            <appender-ref ref="RollingFile2"/>
        </AsyncLogger>
        <Root level="debug">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="RollingFile"/>
        </Root>
    </Loggers>
</Configuration>

测试代码：

public class Main {

    public static void main(String args[]) {

        Logger logger = LogManager.getLogger(Main.class);

        Logger logger2 = LogManager.getLogger("RollingFile2"); 

        Person person = new Person("Li", "lei");

        logger.info("hello, {}", person);

        logger2.info("good bye, {}", person);

}
View Code

 在加载log4j2.xml的启动阶段，如果检测到配置了AsyncRoot或AsyncLogger，将启动一个disruptor实例。

生产者生产消息：当运行到类似于logger.info、logger.debug的输出语句时，将生成的LogEvent放入RingBuffer中。

消费者消费消息：

如果RingBuffer中有LogEvent需要处理，EventProcessor线程从RingBuffer中取出LogEvent，调用Logger相关联的Appender输出LogEvent（具体输出过程与同步过程相同，同样需要过滤器过滤、PatternLayout格式化等步骤）。

如果RingBuffer中没有LogEvent需要处理，EventProcessor线程将处于等待阻塞状态（默认策略）。虽然在log4j2.xml中配置了多个AsyncLogger，但是并不是每个AsyncLogger对应着一个处理线程，而是仅仅有一个EventProcessor线程进行日志的异步处理。

 

 

 

同步异步打印方式对比

 sync 同步打印日志，日志输出与业务逻辑在同一线程内，当日志输出完毕，才能进行后续业务逻辑操作

Async Appender 异步打印日志，内部采用ArrayBlockingQueue，对每个AsyncAppender创建一个线程用于处理日志输出。
Async Logger 异步打印日志，采用了高性能并发框架Disruptor，创建一个线程用于处理日志输出。

 

异步日志生产问题：

1、京东：记一次由线上事故引发的Log4j2日志异步打印优化分析 

     https://developer.jdcloud.com/article/3587 

 // 当服务端系统出现问题时，生成的大量堆栈信息需要通过WARN和ERROR日志打印出来，RingBuffer被填满以后，又触发了锁竞争，由于等待的线程较多，系统中多个业务线程由并行变成了串行，并由此带来了一系列的连锁反应。

log4j2.asyncQueueFullPolicy　　用于指定当日志打印队列被打满的时候，如何处理尚无法正常打印的日志事件，如果不指定的话，默认（Default）是阻塞，建议使用丢弃（Discard）。

log4j2.discardThreshold　　　　用于配合log4j2.asyncQueueFullPolicy使用，指定哪些日志级别及以下的日志事件可以执行丢弃操作，默认为INFO，建议使用ERROR。

 

2、美团：日志导致线程Block的这些坑，你不得不防

 https://tech.meituan.com/2022/07/29/tips-for-avoiding-log-blocking-threads.html   

image

 日志异步处理流程示意如图26所示，整体步骤如下：

  1. 业务线程组装日志事件对象，如创建日志快照或者初始化日志字段等。
  2. 日志事件对象入队，如BlockingQueue队列或Disruptor RingBuffer队列等。
  3. 日志异步线程从队列获取日志事件对象，并输出至目的地，如本地磁盘文件或远程日志中心等。

对应地，Log4j2导致线程Block的主要潜在风险点如下：

  1. 如上图标号①所示，日志事件对象在入队前，组装日志事件时触发了异常堆栈类解析、加载，从而引发线程Block。
  2. 如上图标号②所示，日志事件对象在入队时，由于队列满，无法入队，从而引发线程Block。
  3. 如上图标号③所示，日志事件对象在出队后，对日志内容进行格式化处理时触发了异常堆栈类解析、加载，从而引发线程 Block。

从上述分析不难看出：

  1. 标号①和②处如果发生线程Block，那么会直接影响业务线程池内的所有线程。
  2. 标号③出如果发生线程Block，那么会影响日志异步线程，该线程通常为单线程。

标号①和②处发生线程Block的影响范围远比标号③更大，因此核心是要避免日志事件在入队操作完成前触发线程Block。其实日志异步线程通常是单线程，因此对于单个Appender来说，不会出现Block现象，至多会导致异步线程处理速度变慢而已，但如果存在多个异步Appender，那么多个日志异步线程仍然会出现彼此Block的现象。

 入队前避免线程Block

  1. 日志事件入队前避免触发异常堆栈类解析、加载操作。
  2. 禁用JVM反射调用优化。
  3. 升级JDK版本修复Lambda类Bug。

 入队时避免线程Block

  1. 日志队列满时，Appender忽略该日志。
  2. Appender使用自定义的ErrorHandler实现处理日志。
  3. 关闭StatusConfigListener日志输出。

出队后避免线程Block

在异常格式化转换时避免解析、加载异常堆栈类

 

posted @ 2023-01-20 14:51  飞翔在天  阅读(212)  评论(0)    收藏  举报