日志全链路追踪之MDC

1.引言

Hi，大家好，我是有清

苏格拉底说过：日志打得好，排查没烦恼

我们日常的开发工作中，排查问题去看日志应该是家常便饭的事，日志可以帮助我们清楚的知道当前代码的走向以及链路数据，通常我们现在都是微服务的架构，那么在我们 A 系统调用到 B 系统中，B 系统又调用 C 系统

在繁忙的日志中，我们如何全链路追踪一笔调用呢，通常我们会借助到全局流水号这样的概念，例如下图这样

实现这样的追踪方式有很多种，我们今天入门比较经典实现方式的一种-MDC，MDC 是 SLF4J 提供的一种方便在多线程下记录日志的工具类，可以帮助我们快速实现我们上述说到的全局流水号的打印

2.基本使用

2.1 日志格式配置

2.2 主线程下进行日志打印

我们可以看到输出中将我们的 trace_id 打印出了，就是这么简单

2.3 多线程下进行日志打印

我们刚才在引言中说过，MDC 支持在多线程下进行日志打印，接下来我们同样来一个小 demo 看看

同样实现了，我们的诉求，那么，MDC 为何如此丝滑的实现了我们的想法呢？

3.源码解析

debug 之下无秘密

MDC.put(TRACE_ID, UUID.randomUUID().toString());

我们先从这个 put 方法点击进去，看看 MDC 到底是何方神圣

public static void put(String key, String val)  
    throws IllegalArgumentException {  
  if (key == null) {  
    throw new IllegalArgumentException("key parameter cannot be null");  
  }  
  if (mdcAdapter == null) {  
    throw new IllegalStateException("MDCAdapter cannot be null. See also "  
        + NULL_MDCA_URL);  
  }  
  mdcAdapter.put(key, val);  
}

可以看出来，其实主要借助的是这个这个 mdcAdapter 这个类，这个 Adapter，是什么意思么。过了四级的小伙伴举手了，这个就是适配器的意思，对就是适配器

那么，有一道经典面试必问题不就有答案了么，你看过框架中的设计模式么？我看过 SLF4J 中的的适配器模式，它提供的 mdcAdapter，但是具体实现是交由系统中的日志组件，比如我项目中使用的 LogBack，那么 LogBack 就提供了 LogbackMDCAdapter

在 MDC 类的的静态方法中，直接实现了 mdcAdapter 的加载

static {  
  try {  
    mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();  
  } catch (NoClassDefFoundError ncde) {  
    mdcAdapter = new NOPMDCAdapter();  
    String msg = ncde.getMessage();  
    if (msg != null && msg.indexOf("StaticMDCBinder") != -1) {  
      Util.report("Failed to load class "org.slf4j.impl.StaticMDCBinder".");  
      Util.report("Defaulting to no-operation MDCAdapter implementation.");  
      Util  
          .report("See " + NO_STATIC_MDC_BINDER_URL + " for further details.");  
    } else {  
      throw ncde;  
    }  
  } catch (Exception e) {  
    // we should never get here  
    Util.report("MDC binding unsuccessful.", e);  
  }  
}

这边获取到的 mdcAdapter 即 LogbackMDCAdapter，为什么可以如此无感的获取到呢，其实这边还有一种机制就是 SPI 机制，感兴趣的小伙伴可以研究一下

那么知道了其实是 LogbackMDCAdapter 起作用，我们再进一步看下，LogbackMDCAdapter 的源码

public void put(String key, String val) throws IllegalArgumentException {  
    if (key == null) {  
        throw new IllegalArgumentException("key cannot be null");  
    }  
  
    Map oldMap = copyOnThreadLocal.get();  
    Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);  
  
    if (wasLastOpReadOrNull(lastOp) || oldMap == null) {  
        Map newMap = duplicateAndInsertNewMap(oldMap);  
        newMap.put(key, val);  
    } else {  
        oldMap.put(key, val);  
    }  
}

LogbackMDCAdapter 中的 put 方法看起来也很朴素，我们一行行来看，首先对 key 进行判空处理，如果是空的，那么你存个 der，异常抛出

 Map oldMap = copyOnThreadLocal.get();  

这一段是为了获取上次操作的 map，copyOnThreadLocal 听起来就是为了复制上次的 ThreadLocal，其实也是我们的数据存放的地方

Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);

紧接着通过 WRITE_OPERATION 获取 lastOp，这个last 就是 lastOperation，翻译一下 最后一次的操作， WRITE_OPERATION 默认为 1

if (wasLastOpReadOrNull(lastOp) || oldMap == null)

private boolean wasLastOpReadOrNull(Integer lastOp) {  
    return lastOp == null || lastOp.intValue() == MAP_COPY_OPERATION;  
}

这边的 wasLastOpReadOrNull，通过函数名字我们可以知道，是为了判断最后一次操作是不是读操作或者是第一次进来写操作

这边为什么要判断是不是读操作其实是为了确认最后一次快照读的数据的正确性，但是如果使用 MDC 接口直接进行操作，是不会涉及到快照读的数据的正确性，无需深究

Map newMap = duplicateAndInsertNewMap(oldMap);  
newMap.put(key, val);

private Map duplicateAndInsertNewMap(Map oldMap) {  
    Map newMap = Collections.synchronizedMap(new HashMap());  
    if (oldMap != null) {  
        // we don't want the parent thread modifying oldMap while we are  
        // iterating over it        
        synchronized (oldMap) {  
            newMap.putAll(oldMap);  
        }  
    }  
  
    copyOnThreadLocal.set(newMap);  
    return newMap;  
}

这边会构造一个线程安全的 newMap，并且锁住旧 map，这边我们知道 oldMap 其实已经是线程安全的 map 了，那么为何又加了一把锁呢？这边考虑的很全面，为什么加锁呢，是因为Collections.synchronizedMap 的父子线程是可以重入的，再加一把锁避免父线程对数据进行篡改

至于为何不使用 CurrentHashMap，我也没有猜透，莫非仅仅是为了面向接口编程，使用 Collections.synchronizedMap 保证可以接受任何的 Map 实例？

如果不是第一次进来或者上次操作是写的话，直接会对 oldMap 直接再进行赋值

简单做个总结，MDC 实现的原理其实很简单，就是利用 ThredLocal 保证不同线程下的 Key 不受影响

4.MDC 局限性

在理解了 MDC 的实现之后，比较有经验的小伙伴应该就会想出 MDC 的局限性，那就是父子线程无法传递数据的问题

show me code

我们在 main 线程设置了 traceId，但是开启线程池之后，却没有将我们的 traceId 打印出来，当然官方文档也解释了这一问题：
logging.apache.org/log4j/2.x/m…

其实官方就是推荐我们使用 InheritableThreadLocal 去实现父子线程的值传递

当然我们还可以在子线程中直接捞出 MDC 中的 Map，强行进行赋值，示例代码如下

当然也有现有框架帮我们直接一步解决了这种弊端，感兴趣的小伙伴可以去体验一下

闲言碎语

写完这篇文章的时候，电脑正在播放着梁博的日落大道

每次听这首歌，总有一种感觉，自己开着车，在一望无际的公路上行驶

在车上，会看到暖风将至，会看到温柔满意，会看到黄昏追逐黎明，会看到那耀眼的金黄