经常做线上问题排查的可能会有感受,由于日志打印一般是无序的,多线程下想要串行拿到一次请求中的相关日志简直是大海捞针。那么MDC是一种很好的解决办法。
SLF4J 提供了MDC ( Mapped Diagnostic Contexts )功能,它的实现也是利用了 ThreadLocal 机制。 在代码中,只需要将指定的值 put 到线程上下文的 Map 中,然后在对应的地方使用 get 方法获取对应的值,从而达到自定义和修改日志输出格式内容的目的。
例如以下受log4j2.xml模板:
<Pattern>%d %p [%c] [%X{key1},%X{key2}]- %m%n</Pattern>
在日志模板log4j2.xml中,使用 %X{} 来占位,内容会替换为对应MDC 中 key的值,以达到自定义日志格式的效果。
在链路跟踪框架中,其实扩展MDC很简单,只需在log span的before方法中塞入traceId与spanId,在after方法中进行清理逻辑即可。
private void beforeStartSpan(Span span){ MDC.put(TraceKeys.TRACE_ID, span.getTraceId()); MDC.put(TraceKeys.SPAN_ID, span.getSpanId()); } private void afterEndSpan(Span span){ MDC.remove(TraceKeys.TRACE_ID); MDC.remove(TraceKeys.SPAN_ID); if (span != null) { MDC.put(TraceKeys.TRACE_ID, currentSpan.getTraceId()); MDC.put(TraceKeys.SPAN_ID, currentSpan.getParentId()); //此处需要塞回parent span的spanId } }
那么在log4j2.xml中配置:
<Pattern>%d %p [%c] [%X{TraceId},%X{SpanId}]- %m%n</Pattern> //在合适的地方加入 [%X{TraceId},%X{SpanId}] 即可
这样输出日志即为:
2019-01-29 19:06:15,482 INFO [com.fredal.TestController] [e9b84d301f73f6e1a6386f216fa0120d,9296f83b058675d2]- this is a test in test 2019-01-29 19:06:15,489 INFO [com.fredal.TestController] [e9b84d301f73f6e1a6386f216fa0120d,f435c1cb819db821]- this is a test in test/provider
由于MDC是基于Threadlocal的,那么如果一个请求中有异步的逻辑,那么异步过程中的日志是取不到MDC中的值的。
这也是个老生常谈的问题了,由于我们的全链路跟踪框架已经使用Transmittable ThreadLocal改造过了,见 调用链跨线程传递THREADLOCAL对象 ,所以在异步线程中也是同样能获得的MDC的值的。