文章目录
一、背景
使用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保存了两份。