转载自: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. 三者之间的关系
initialValue: 初始化线程局部变量的初始值。beforeExecute: 在任务执行前,将父线程的上下文信息传递给当前线程。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保存了两份。