Slf4j MDC使用transmittable-thread-local解决多线程日志跟踪(转载)

496 阅读6分钟

转载自:blog.csdn.net/xiaolong771…

一、背景

使用Slf4j的MDC方案可以在日志中打印TraceID来实现链路追踪,可以很好的帮助定位线上问题,但是传统的MDC方案不能处理线程池或者其他的异步场景,为此研究下其他的解决方案。

二、其他的解决思路

1、使用logback/log4j官网推荐的方案,链接

logback.qos.ch/manual/mdc.… 具体是显示调用 MDC.getCopyOfContextMap() 和 MDC.setContextMap() ,在向线程池提交任务的时候需要显示的去调用。

这种方式很繁琐,而且侵入性很高,可维护性也很低。juejin.cn/post/684490…www.cnblogs.com/wanghongsen… 这2篇文章就是这种思路,包装了原始的线程池、Runable、Thread去实现的。

2、使用阿里的TransmittableThreadLocal方案

具体是使用TransmittableThreadLocal的实现去增强ThreadPoolExecutor,不需要在任务提交运行的时候去显示的调用MDC,但是TransmittableThreadLocal的官网上没有明确的结合MDC的教程。

网上的实现主要有2种,一种是自己实现一个MDCAdapter替换logback/log4j的MDCAdapter,内部将其ThreadLocal替换为TransmittableThreadLocal的实现,在通过其他方式注入到日志框架中。

另外一种方式是使用 logback-mdc-ttl 来更换项目中的logback框架,内部的思路和上面类似,也是替换了MDCAdapter的实现。

这2种方式都有很大的问题,第一种需要修改日志框架的注入实现,在后续升级日志框架有很大的风险。第二种方式是引入了一个三方的日志框架,不可维护。

blog.csdn.net/singgel/art…juejin.cn/post/698183… 都是按照上面的2种方式实现的。

三、优化后的解决方案

总结来看上述几种解决方案都不太理解,第二种方式虽然使用了TransmittableThreadLocal解决了包装类的问题,但是没有很好的适配MDC,修改了大量的实现代码,而且不利于后续的升级维护。 在搜索的相关的资料、源码以及TransmittableThreadLocal的issue里,发现了一种比较简洁的实现方式。具体代码如下:

添加 HandlerInterceptor 拦截器,核心的实现思路是实现 TransmittableThreadLocal 的 initialValue,beforeExecute,afterExecute接口,在多线程数据传递的时候,将数据复制一份给MDC。

@Component
public class TraceIdInterceptor implements HandlerInterceptor {

    /**
     * 实现 TransmittableThreadLocal 的 initialValue,beforeExecute,afterExecute接口
     */
    static TransmittableThreadLocal<Map<String, String>> ttlMDC = new TransmittableThreadLocal<>() {
        /**
         * 在多线程数据传递的时候,将数据复制一份给MDC
         */
        @Override
        protected void beforeExecute() {
            final Map<String, String> mdc = get();
            mdc.forEach(MDC::put);
        }

        @Override
        protected void afterExecute() {
            MDC.clear();
        }

        @Override
        protected Map<String, String> initialValue() {
            return Maps.newHashMap();
        }
    };


    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        //MDC记录traceId
        String traceId = IdUtil.fastUUID();
        MDC.put("traceId", traceId);

        //同时给TransmittableThreadLocal记录traceId
        ttlMDC.get().put("traceId", traceId);

        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
        @Nullable Exception ex) {

        //清除数据
        MDC.clear();
        ttlMDC.get().clear();
        ttlMDC.remove();
    }
}

1. initialValue()

  • 作用: 初始化 TransmittableThreadLocal 的初始值。

  • 调用时机: 当线程第一次访问 TransmittableThreadLocal 时调用。

  • 返回值: 返回一个初始值,通常是一个空对象(如 new HashMap())。

  • 典型实现:

    @Override
    protected Map<String, String> initialValue() {
        return Maps.newHashMap();
    }

2. beforeExecute()

  • 作用: 在任务执行前,将父线程的上下文信息传递给当前线程。

  • 调用时机: 在线程池中执行任务前调用。

  • 典型实现:

    @Override
    protected void beforeExecute() {
        final Map<String, String> mdc = get();
        mdc.forEach(MDC::put);
    }

3. afterExecute()

  • 作用: 在任务执行后,清理当前线程的上下文信息。
  • 调用时机: 在线程池中执行任务后调用。
  • 典型实现:
@Override
protected void afterExecute() {
    MDC.clear();
}
  • 使用场景: 用于清理当前线程的上下文信息,避免污染后续任务。例如,清除 MDC 中的数据。

4. 三者之间的关系

  1. initialValue: 初始化线程局部变量的初始值。
  2. beforeExecute: 在任务执行前,将父线程的上下文信息传递给当前线程。
  3. afterExecute: 在任务执行后,清理当前线程的上下文信息。
  • 使用场景: 用于将父线程的上下文信息(如 MDC 数据)复制到当前线程中,确保任务执行时能够访问正确的上下文信息。

  • 使用场景: 用于设置线程局部变量的初始状态。例如,初始化一个空的 Map 来存储线程上下文信息。

使用TransmittableThreadLocal提供的包装池,

@Bean
public Executor asyncExecutor() {
    log.info("start asyncExecutor");
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    //配置核心线程数
    executor.setCorePoolSize(10);
    //配置最大线程数
    executor.setMaxPoolSize(50);
    //配置队列大小
    executor.setQueueCapacity(0);
    //配置线程池中的线程的名称前缀
    executor.setThreadNamePrefix("async-service-");

    // rejection-policy:当pool已经达到max size的时候,如何处理新任务
    // CALLER_RUNS:不在新线程中执行任务,而是有调用者所在的线程来执行
    executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
    //执行初始化
    executor.initialize();
    //使用TransmittableThreadLocal提供的包装池
    return TtlExecutors.getTtlExecutor(executor);
}

如果项目中使用到了ForkJoinPoll类似的,也需要包装。

logback配置,

    <!--用户操作日志, 按照每天生成日志文件 -->
    <appender name="OPERATE_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <!--日志文件输出的文件名-->
            <FileNamePattern>${LOG_HOME}/operate.log.%d{yyyy-MM-dd}.%i.log</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>180</MaxHistory>
            <!--日志文件最大的大小-->
            <MaxFileSize>10MB</MaxFileSize>
            <!--文件总大小-->
            <TotalSizeCap>10GB</TotalSizeCap>
            <!--系统启动时清理-->
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--格式化输出:%d表示日期,%thread表示线程名,%-5level:级别从左显示5个字符宽度%msg:日志消息,%n是换行符-->
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%thread] %-5level %logger{50} - %msg%n</pattern>
        </encoder>
    </appender>

最终效果,

2022-10-11 11:06:59.996 [20300f1f-f056-47ab-91a9-962138b42cf7] [async-service-3] INFO  c.knowledge.server.aop.GremlinLogAspect[doAround:53] -  ==> Method: public java.lang.String com.knowledge.server.service.GremlinService.gremlinForMultiPropertiesV2(java.util.List,boolean)
2022-10-11 11:06:59.996 [20300f1f-f056-47ab-91a9-962138b42cf7] [async-service-3] INFO  c.knowledge.server.aop.GremlinLogAspect[doAround:54] -  ==> Preparing: g.E('1tml8g-163844e11d8205edf16abb7a57e6f0200-3dp1-19f147fb008bcc04b178e67e4a5997b5c','1tmnls-163844e11d8205edf16abb7a57e6f0200-3dp1-1b736de17b5bd262a6668d66c2a733cdb','1tmn7k-164709fefe930f5e71510554004811850-3dp1-14328fa1b81e88842eec5911e1d06e4fd').elementMap()
2022-10-11 11:07:00.007 [20300f1f-f056-47ab-91a9-962138b42cf7] [https-jsse-nio-8001-exec-9] INFO  OPERATE[doAround:175] - [operate action record] {"accountType":"INNER","basePath":"https://127.0.0.1:8001","description":"获取一批边数据","ip":"10.33.113.5","isSuccess":1,"method":"GET","module":"开放接口","spendTime":670,"startTime":1665457619336,"uri":"/knowledge-graph/openapi/v1/edges/hasWife/3","url":"https://127.0.0.1:8001/knowledge-graph/openapi/v1/edges/hasWife/3","username":"openapi"}

可以看到在线程池里也打印出了traceId。

四、总结

使用上述方案,整体的代码改动量很小,侵入性很低,唯一的缺陷可能是traceId同时在MDC里和TransmittableThreadLocal保存了两份。

参考资料

github.com/alibaba/tra… 原文链接:blog.csdn.net/xiaolong771…