先从问题说起
线上发现一个问题,日志里的traceId数据是错误的。排查后发现是新同学近期引入线程池时,子线程没有更新MDC里数据引起的。
看下代码,就是常规的线程池使用:
这里就要引入MDC的特性了。
MDC介绍
MDC(Mapped Diagnostic Context,映射调试上下文)是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的类。
MDC类,简单来说就是日志的增强功能,如果配置了MDC,并添加了相应的key-value对,就会在打印日志的时候把key对应的value打印出来。
MDC内部是用ThreadLocal实现的,可以携带当前线程的context信息。
实现
MDC类(slf4j包)中包装了一个MDCAdapter(接口),不同的log包有不同的实现。log4j 中实现类是 Log4jMDCAdapter,logback 的实现类是 LogbackMDCAdapter。
MDC类中put(),get() 等方法均是调用其成员的mdcAdapter实现。我们代码中是 log4j 实现的,这里的代码切图,都来自log4j。MDC的管理是基于一个线程,然后子线程自动的继承它的父线程的MDC的副本。
这里MDC.put()是放到了tlm这个threadLocalMap里。
ThreadLocalMap继承自InheritableThreadLocal,在创建线程时,子线程会复制父线程的inheritableThreadLocals变量,从而拿到父线程中的信息。
产生问题原因
子线程在创建的时候会把父线程中的inheritableThreadLocals变量设置到子线程的inheritableThreadLocals中,而MDC内部是用InheritableThreadLocal实现的,所以自然会把父线程中的上下文带到子线程中。
但对于线程池中的线程来说,这部分线程是可以重用的,但是线程本身只会初始化一次,所以之后重用线程的时候,就不会进行初始化操作了,也就不会有上一段中提到的父线程inheritableThreadLocals拷贝到子线程中的过程了。
线上的traceId是在入口层统一处理了MDC的put()和remove(),然而代码中创建的线程池则没有处理这些。代码中使用的是线程池内子线程第一次创建时,copy自当时父线程的数据。因为子线程内没有更新策略,子线程自己也不会主动更新。导致日志内记录的traceId不会更新。
解决方法:可以在将任务提交给执行程序之前,在原始(主)线程上调用MDC.getCopyOfContextMap()得到当前线程的context拷贝。当任务运行时,作为其第一个操作,调用MDC.setContextMapValues()将原始MDC值的存储副本与新的Executor管理线程关联起来。