MDC使用手册精讲

MDC

背景： 线上排查问题时，请求在多个微服务之间进行调用，并发量较大的情况下，想跟踪某一个请求的链路，是需要花费一些时间才能梳理出来，而且还依赖于你的业务字段。而我们需要的是快速定位，快速纠错，因此就需要一个唯一的全局标识用来识别并跟踪这个请求。

想法： 一个唯一全局标识，并且还能在上下游之间进行传递，那可以对这个请求 request 做些特殊操作，我们可以在请求头上添加这个全局标识，比如使用UUID，在进入每一个微服务之前进行拦截 （filter/intercept），获取这个UUID并设置到当前线程中。输出日志时，就把这个UUID也输出到日志中，这样便可以快速识别并定位。如果在业务代码中使用了多线程，也应该记录，这就需要使用到本次介绍的重点内容：MDC

介绍： MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。MDC 中包含的内容可以被同一线程中执行的代码所访问，当前线程的子线程也会继承其父线程中的 MDC 的内容。

我们日志用的是 slf4j + logback，看看 slf4j-api 包结构，发现了一个 spi ，是不是很熟悉，虽然这个 spi 只是一个包名，但是实质是一样的

在 slf4j-api 包下有一个 MDCAdapter接口，如下

public interface MDCAdapter {
  //通过k-v设置  
  public void put(String key, String val);

  public String get(String key);

  public void remove(String key);

  public void clear();

  public Map getCopyOfContextMap();

  public void setContextMap(Map contextMap);
}

由于使用的是logback日志，对应的logback也提供了MDCAdapter接口的实现，如下

我们看看logback里面是如何实现 MDCAdapter 接口的。发现是基于InheritableThreadLocal 来实现的，这个就很好的处理的父子线程的问题，也就是可以trace线程池

public final class LogbackMDCAdapter implements MDCAdapter {

  final InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal<Map<String, String>>();

  private static final int WRITE_OPERATION = 1;
  private static final int READ_OPERATION = 2;

  // keeps track of the last operation performed
  final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();

  private Integer getAndSetLastOperation(int op) {
    Integer lastOp = lastOperation.get();
    lastOperation.set(op);
    return lastOp;
  }

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

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

    copyOnInheritThreadLocal.set(newMap);
    return newMap;
  }

  public void put(String key, String val) throws IllegalArgumentException {
    if (key == null) {
      throw new IllegalArgumentException("key cannot be null");
    }

    Map<String, String> oldMap = copyOnInheritThreadLocal.get();
    Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);

    if (wasLastOpReadOrNull(lastOp) || oldMap == null) {
      Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
      newMap.put(key, val);
    } else {
      oldMap.put(key, val);
    }
  }

  public void remove(String key) {
    if (key == null) {
      return;
    }
    Map<String, String> oldMap = copyOnInheritThreadLocal.get();
    if (oldMap == null) return;

    Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);

    if (wasLastOpReadOrNull(lastOp)) {
      Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
      newMap.remove(key);
    } else {
      oldMap.remove(key);
    }
  }

  public void clear() {
    lastOperation.set(WRITE_OPERATION);
    copyOnInheritThreadLocal.remove();
  }

  public String get(String key) {
    Map<String, String> map = getPropertyMap();
    if ((map != null) && (key != null)) {
      return map.get(key);
    } else {
      return null;
    }
  }

  public Map<String, String> getPropertyMap() {
    lastOperation.set(READ_OPERATION);
    return copyOnInheritThreadLocal.get();
  }

  public Set<String> getKeys() {
    Map<String, String> map = getPropertyMap();
    if (map != null) {
      return map.keySet();
    } else {
      return null;
    }
  }

  public Map getCopyOfContextMap() {
    lastOperation.set(READ_OPERATION);
    Map<String, String> hashMap = copyOnInheritThreadLocal.get();
    if (hashMap == null) {
      return null;
    } else {
      return new HashMap<String, String>(hashMap);
    }
  }

  @SuppressWarnings("unchecked")
  public void setContextMap(Map contextMap) {
    lastOperation.set(WRITE_OPERATION);

    Map<String, String> newMap = Collections.synchronizedMap(new HashMap<String, String>());
    newMap.putAll(contextMap);

    //赋值给threadlocal
    copyOnInheritThreadLocal.set(newMap);
  }
}

那么日志的输出格式是怎么样的呢？

MDC使用 %X{key} 来定义日志格式，会在此处打印MDC设置的key的value，如果所定义的key不存在，那么将不会打印，会留一个占位符

<configuration>
    　　　<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    　　　　　 <encoder>
    　　　　　　　　　<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level [%X{requestId}] %logger{36} - %msg%n</pattern>
    　　　　　 </encoder>
    　　　</appender>

    　　　<root level="DEBUG">
    　　　　　　<appender-ref ref="STDOUT" />
    　　　</root>
</configuration>

实战测试

public static void main(String[] args) throws InterruptedException {
    MDC.put("requestId","这是我的全局唯一标识UUID");
    log.error("===========我是父线程main=============");
    new Thread(()-> {
        log.error("===========我是子线程child================");
    }).start();
    TimeUnit.SECONDS.sleep(3);
}

2024-04-16 20:28:42.498 [main] ERROR [这是我的全局唯一标识UUID] com.example.ssm.SsmApplication - ===========我是父线程main=============
2024-04-16 20:28:42.499 [Thread-1] ERROR [这是我的全局唯一标识UUID] com.example.ssm.SsmApplication - ===========我是子线程child================

现在我们已经可以在多个服务之间实现问题精准定位，但是还是需要在各个服务器上去取日志，因此我们可以进行日志的统一收集，比如常见的ELK（ Elasticsearch+Logstash +Kibana），LPG（ Loki+Promtail+Grafana）方案。