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

2023-09-12 08:19:44

文章目录

一、背景

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

二、其他的解决思路

1、使用logback/log4j官网推荐的方案，链接 https://logback.qos.ch/manual/mdc.html#managedThreads

具体是显示调用 MDC.getCopyOfContextMap() 和 MDC.setContextMap() ，在向线程池提交任务的时候需要显示的去调用。

这种方式很繁琐，而且侵入性很高，可维护性也很低。

https://juejin.cn/post/6844904101483020295 和https://www.cnblogs.com/wanghongsen/p/12029394.html 这2篇文章就是这种思路，包装了原始的线程池、Runable、Thread去实现的。

2、使用阿里的TransmittableThreadLocal方案

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

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

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

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

https://blog.csdn.net/singgel/article/details/102495415 和 https://juejin.cn/post/6981831233911128072#heading-5 都是按照上面的2种方式实现的。

三、优化后的解决方案

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

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

@ComponentpublicclassTraceIdInterceptorimplementsHandlerInterceptor{/**
     * 实现 TransmittableThreadLocal 的 initialValue,beforeExecute,afterExecute接口
     */staticTransmittableThreadLocal<Map<String,String>> ttlMDC=newTransmittableThreadLocal<>(){/**
         * 在多线程数据传递的时候，将数据复制一份给MDC
         */@OverrideprotectedvoidbeforeExecute(){finalMap<String,String> mdc=get();
            mdc.forEach(MDC::put);}@OverrideprotectedvoidafterExecute(){
            MDC.clear();}@OverrideprotectedMap<String,String>initialValue(){returnMaps.newHashMap();}};@OverridepublicbooleanpreHandle(HttpServletRequest request,HttpServletResponse response,Object handler){//MDC记录traceIdString traceId=IdUtil.fastUUID();
        MDC.put("traceId", traceId);//同时给TransmittableThreadLocal记录traceId
        ttlMDC.get().put("traceId", traceId);returntrue;}@OverridepublicvoidafterCompletion(HttpServletRequest request,HttpServletResponse response,Object handler,@NullableException ex){//清除数据
        MDC.clear();
        ttlMDC.get().clear();
        ttlMDC.remove();}}

使用TransmittableThreadLocal提供的包装池，

@BeanpublicExecutorasyncExecutor(){
    log.info("start asyncExecutor");ThreadPoolTaskExecutor executor=newThreadPoolTaskExecutor();//配置核心线程数
    executor.setCorePoolSize(10);//配置最大线程数
    executor.setMaxPoolSize(50);//配置队列大小
    executor.setQueueCapacity(0);//配置线程池中的线程的名称前缀
    executor.setThreadNamePrefix("async-service-");// rejection-policy：当pool已经达到max size的时候，如何处理新任务// CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行
    executor.setRejectedExecutionHandler(newThreadPoolExecutor.CallerRunsPolicy());//执行初始化
    executor.initialize();//使用TransmittableThreadLocal提供的包装池returnTtlExecutors.getTtlExecutor(executor);}

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

logback配置，

<!--用户操作日志， 按照每天生成日志文件 --><appendername="OPERATE_FILE"class="ch.qos.logback.core.rolling.RollingFileAppender"><rollingPolicyclass="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><encoderclass="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-1111: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-1111: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-1111: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保存了两份。