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 performedfinal 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 itsynchronized (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);//赋值给threadlocalcopyOnInheritThreadLocal.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）方案。