我竟然才知道slf4j里还有个MDC

大家好久不见，我是walking。今天给大家带来一个日志方面的知识——MDC，不知道大家认识不，反正我是最近刚知道的😂

初见MDC

前两天看项目中的代码，无意中看到一个自定义的线程池

MDCThreadExecutor extends ThreadPoolTaskExecutor

主要针对spring-context 中的 ThreadPoolTaskExecutor 线程池进行了扩展，但也没做多少扩展，仅仅是引入了两个属性，如下：

private Map<String, String> threadContext;
private Boolean useThreadContext;
public Map<String, String> getThreadContext() {
    return useThreadContext ? (threadContext == null ? MDC.getCopyOfContextMap() : threadContext) : null;
}

然后对 execute(Runnable task) 和 submit(Runnable task) 这两个方法进行了重写，如下：

@Override
public void execute(Runnable task) {
    super.execute(getMDCTask(task, getThreadContext()));
}
@Override
public Future<?> submit(Runnable task) {
    return super.submit(getMDCTask(task,getThreadContext()));
}

我看到使用了 MDC.java 这个东西，第一反应就是，卧槽，MDC是什么？用这个干嘛？没见过啊，所以我就想研究研究，瞻仰一下人家的代码，于是就有了这篇文章。

自行探索

我很好奇这是什么东西，点进去看是 slf4j 包里的一个类，而自定义扩展线程池的这个类里仅仅使用了这个 MDC 做了一些简单的操作，如下代码：

private Runnable getMDCTask(Runnable task, Map<String, String> threadContext) {
     return () -> {
         if (useThreadContext) {
             MDC.setContextMap(threadContext);
             MDC.put("tranceID", UUID.randomUUID().toString().replaceAll("-",""));
         }else{
             MDC.setContextMap(null);
         }
         try {
            task.run();
        } finally {
            MDC.remove("tranceID");
            MDC.clear();
        }
    };
}

仅仅是对提交的任务做了一层包装，往MDC里put了tranceId，value为一个UUID字符串，这样写的作用是什么呢？因为写这个的人已经离职，也没法问了，那就自己研究研究呗。

点进去put方法看看，代码如下：

/** 
  * 将由key参数标识的诊断上下文值（val参数）放入当前线程的诊断上下文映射中。
  * 键参数不能为空。仅当基础实现支持val参数时，它才能为null。
  * 此方法将所有工作委托给底层日志系统的MDC。
  * 
  * @param key non-null key 
  * @param val value to put in the map
  * 
  * @throws IllegalArgumentException 参数key为空时抛出异常
 */
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);
}

根据注释我们可以大概知道这个意思，把一个key-value键值对put到map里，底层大概是对map进行操作的，我们可以看到上面代码第18行 mdcAdapter.put(key, val); 最终执行的是 org.slf4j.spi.MDCAdapter.java 这个接口类定义的put的方法。这个接口又是什么呢？注释是这样解释的：

这个接口抽象了各种MDC实现提供的服务。

接口中对put方法的注释如下：

将由key参数标识的上下文值（val参数）放入当前线程的上下文映射中。键参数不能为空。仅当基础实现支持val参数时，它才能为null。
如果当前线程没有上下文映射，则创建它作为此调用的副作用。

而类名以Adadiaoer结尾表明它是一个适配器，我们都知道 slf4j 是一套日志接口门面（就像JDBC一样），它的实现有logback，log4j等。所以我们需要进到他的实现中去一探究竟，因为我们用的是logback那当然看logback相关的了

LogbackMDCAdapter类上的注释如下：

映射诊断上下文（Mapped Diagnostic Context，简称MDC）是一种工具，用于区分不同来源的交错日志输出。当服务器几乎同时处理多个客户机时，日志输出通常是交错的。
MDC是基于每个线程进行管理的。子线程自动继承其父线程的映射诊断上下文的副本。

看到这我们就大概知道了MDC的基本作用了，我们之前用日志框架都知道，有5种日志级别，trace、debug、info、warn、error，而MDC是对日志的扩展应用，它应该能够允许我们自定义想要展示在日志的信息，看上面的注释，我们应该能够了解到，MDC在多线程环境下有很大的用处，可以管理每个线程的日志。

好了，这些都是我们通过大致的浏览它的源码上的注释得知的，是不是这样还有待验证。我们继续看一下put操作的实现，如下：

 /** 
  * 将由key参数标识的上下文值（val参数）放入当前线程的上下文映射中。
  * 注意，与log4j相反，val参数可以为null。
  * 如果当前线程没有上下文映射，则创建它作为此调用的副作用。
  * @throws IllegalArgumentException 参数key为空时抛出异常
  */
 public void put(String key, String val) throws IllegalArgumentException {
     if (key == null) {
         throw new IllegalArgumentException("key cannot be null");
    }
    Map<String, String> oldMap = copyOnThreadLocal.get();//ThreadLocal调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);
    }
}

上面的代码也很简单，从ThreadLocal中获取保存的map把我们的key-value放进去就完事了。我们知道了原来它是用ThreadLocal来保存我们自定义的线程上下文信息的。

MDC功能测验

以上，我们大致知道了MDC做了什么了。这仅仅是我们自己看了别人在项目代码里用MDC以及MDC的一点源码得到的一些信息。我们还要到网上查一下资料，一是看我们以上的认知是不是对的，二是获取关于MDC的更多信息，包括怎么使用。

首先我们用上面的代码，就是自定义的扩展线程池来测试一下，我们put了一个tranceId，value是UUID，看有什么效果。

我写了一个测试接口，如下，简单的模拟一个任务提交到线程池，然后在这个任务内部穿插着调了很多方法，假设很多业务逻辑，并且各个逻辑分支、方法都有自己的日志输出，就是这样的一个测试接口。待会我们测试一下看用了MDC后日志会有什么效果。

@GetMapping("testMDCThreadPool")
 public Map<String, Object> testMDCThreadPool() {
     Map<String, Object> successResult = ResultUtil.getSuccessResult();
     log.info("begin....");//在web容器创建的线程里打印日志
     //提交任务
     taskExecutor.execute(() -> {
         log.info("task main......");//在自定义线程池创建的线程里打印日志
         try {
             TimeUnit.MILLISECONDS.sleep(1);
            doSome1();
            //other...
        } catch (InterruptedException e) {
            log.error("task error:{}", e);
        }
    });
    log.info("end....");
    return successResult;
 }
public void doSome1() throws InterruptedException {
    log.info("this is print......");
    TimeUnit.MILLISECONDS.sleep(5);
    doSome2();
    //other...
}
public void doSome2() throws InterruptedException {
    log.info("this is print......");
    TimeUnit.MILLISECONDS.sleep(1);
    //other...
}

然后就是把项目运行起来（一个简单的springboot项目，配了一个我们扩展后的线程池MDCThreadExecutor，构造函数传了一个map，map里放了一个key-value，即mdc-threadPool，然后下面是线程池的一些参数，然后还有我们的线程名是walking-mdc开头的）

 @Bean
 public MDCThreadExecutor taskExecutor(){
     MDCThreadExecutor mdcThreadExecutor = new MDCThreadExecutor(new HashMap<String, String>() {{
         put("appId", "mdc-threadPool");
     }});
     mdcThreadExecutor.setCorePoolSize(10);
     mdcThreadExecutor.setMaxPoolSize(20);
     mdcThreadExecutor.setKeepAliveSeconds(5);
     mdcThreadExecutor.setQueueCapacity(50);
    mdcThreadExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
    mdcThreadExecutor.setThreadFactory(new DefaultThreadFactory("walking-mdc"));
    return mdcThreadExecutor;
}

然后我们访问http://localhost:8899/testMDCThreadPool，观察控制台输出

109-05 21:48:20.478 [http-nio-8899-exec-2] INFO  [c.w.r.controller.MDCTestController] useMDCThreadPool:25 [] []- begin....
209-05 21:48:20.487 [http-nio-8899-exec-2] INFO  [c.w.r.controller.MDCTestController] useMDCThreadPool:37 [] []- end....
309-05 21:48:20.620 [walking-mdc-1-1] INFO  [c.w.r.controller.MDCTestController] lambda$useMDCThreadPool$0:28 [mdc-threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- task main......
409-05 21:48:20.622 [walking-mdc-1-1] INFO  [c.w.r.controller.MDCTestController] doSome1:42 [mdc-threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- this is print......
509-05 21:48:20.628 [walking-mdc-1-1] INFO  [c.w.r.controller.MDCTestController] doSome2:49 [mdc-threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- this is print......

可以看到日志的前两行是web容器线程池创建的线程所打印的日志，因为和我们自己的线程池创建的线程所打印出的线程名不一样（http-nio-8899-exec-xx和walking-mdc-1-xx）。往后看可以看到还有区别，前两行日志中有两个空的中括号[]，[]，而后3行日志中括号里是这样的[mdc-threadPool]、[6c60c8df5ff842adbd8aecef4aca3003]，这不就是我们的往map里放的appId和通过MDC.put放的UUID吗？
噢~在这给区别显示了，实现了打印我们自定义的日志参数。

难道放到线程上下文里就能打印了吗？不会这么智能的吧。所以我全局搜一下appId和tranceId，果然不出所料，在logback-spring.xml里找到了这俩参数的身影。下面代码第3行%X{appId}和%X{tranceId}，所以放进去的参数，在日志打印模板里配置上就能在日志里体现出来。

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>%d{MM-dd HH:mm:ss.SSS} [%thread] %-5level [%logger{38}] %method:%line [%X{appId}] [%X{tranceID}]- %msg%n
    </pattern>
  </encoder>
</appender>

还记得刚才提到的LogbackMDCAdapter类上的注释吗？如下：

映射诊断上下文（Mapped Diagnostic Context，简称MDC）是一种工具，用于区分不同来源的交错日志输出。当服务器几乎同时处理多个客户机时，日志输出通常是交错的。
MDC是基于每个线程进行管理的。子线程自动继承其父线程的映射诊断上下文的副本。

有一句说的很对，当程序在服务器上运行时，情况往往很复杂，多线程运行日志是错综复杂的，多线程的日志是交替的，所以这种情况下我们很难分辨出哪些日志是一个线程或者一个任务打印的。

看到这，恍然大悟了吧，MDC的作用就在这。如果还不明白，那么我们模拟多线程请求刚才们的测试接口看下效果吧。

我模拟了1秒内发10个线程请求，看下日志是什么样的，帮助理解。

如上图，日志交替执行的效果出来了，实际生产环境中并发量比这大，同一个线程的日志有时候会隔很远，无法分辨哪些是同一个线程同一个任务打印的，也就不方便排查问题。而有了MDC，再配合linux的grep用关键字抽取日志，那就方便多了。MDC还挺棒的呢！

以上是通过项目里使用MDC，然后通过自己的小测验和简单的一点源码来对MDC有了一个初步的了解。然后又搜集了一些信息对MDC有个更加全面的认识。

slf4j中MDC是什么鬼

MDC从使用方式上与我们常用的记录日志的方式有些不同，我对它的理解是MDC可以将一个处理线程中你想体现在日志文件中的数据统一管理起来，根据你的日志文件配置决定是否输出。
比如以下但不限于以下场景可以考虑使用MDC来达到目的

我们想在日志中体现请求用户IP地址
用户使用http客户端的user-agent
记录一次处理线程的日志跟踪编号(这个编号目的是为了查询日志方便，结合grep命令能根据跟踪编号将本次的处理日志全部输出)

使用方式

使用方式可以用AOP或Filter或Interceptor或者在自定义的线程池中给每个线程一个唯一的编号（就行我上面那样使用）这类工具配合使用，获得你希望输出到日志的变量并调用MDC.put(String key, String val)。再比如下面AOP中使用

@Around(value = "execution(* com.xx.xx.waling.impl.*.*(..))", argNames="bcdd")
 public Object validator(ProceedingJoinPoint pjp) throws Throwable {
     try {
         String traceId = TraceUtils.begin();
         MDC.put("traceId", traceId);
         Object obj = pjp.proceed(args);
         return obj;
     } catch(Throwable e) {
         //TODO 处理错误
    } finally {
        TraceUtils.endTrace();
    }
}

MDC带来的好处

如果你的系统已经上线，突然有一天老板说我们增加一些用户数据到日志里分析一下。如果没有MDC我猜此时此刻你应该处于雪崩状态。MDC恰到好处的让你能够实现在日志上突如其来的一些需求
如果你是个代码洁癖，封装了公司LOG的操作，并且将处理线程跟踪日志号也封装了进去，但只有使用了你封装日志工具的部分才能打印跟踪日志号，其他部分(比如hibernate、mybatis、httpclient等等)日志都不会体现跟踪号。当然我们可以通过linux命令来绕过这些困扰。
使代码简洁、日志风格统一

小结

到这里MDC就告一段落了，我们了解了MDC的基本使用和好处，小伙伴们你们学会了吗？知道有这个东西，即便是现在用不到，以后如果有需求要实现类似的功能的话，你能第一时间想到可以用MDC就够了，也能装一把逼😄

本文涉及的代码已托管到码云，https://gitee.com/it-wenbei/slf4j-MDC，需要的可以下载啦。

记得点赞、转发，多谢支持啦

之前整理的 redis 和 MQ 的知识点思维导图分享给大家，2K+的小伙伴都领取了你还不快来领~

往期热文：

欢迎关注我哦，谢谢大家的支持

参考：
http://logback.qos.ch/manual/mdc.html
https://www.cnblogs.com/sealedbook/p/6227452.html

posted @ 2020-09-07 12:24 问北阅读(4163) 评论(1) 编辑收藏举报

刷新页面返回顶部

问北

欢迎关注公众号：BiggerBoy