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)方案。