我竟然才知道slf4j裡還有個MDC

為何不是夢發表於2020-09-07

大家好久不見，我是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來達到目的

  1. 我們想在日誌中體現請求使用者IP地址

  2. 使用者使用http客戶端的user-agent

  3. 記錄一次處理執行緒的日誌跟蹤編號(這個編號目的是為了查詢日誌方便，結合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帶來的好處

  1. 如果你的系統已經上線，突然有一天老闆說我們增加一些使用者資料到日誌裡分析一下。如果沒有MDC我猜此時此刻你應該處於雪崩狀態。MDC恰到好處的讓你能夠實現在日誌上突如其來的一些需求

  2. 如果你是個程式碼潔癖，封裝了公司LOG的操作，並且將處理執行緒跟蹤日誌號也封裝了進去，但只有使用了你封裝日誌工具的部分才能列印跟蹤日誌號，其他部分(比如hibernate、mybatis、httpclient等等)日誌都不會體現跟蹤號。當然我們可以通過linux命令來繞過這些困擾。

  3. 使程式碼簡潔、日誌風格統一

小結

到這裡MDC就告一段落了，我們瞭解了MDC的基本使用和好處，小夥伴們你們學會了嗎？知道有這個東西，即便是現在用不到，以後如果有需求要實現類似的功能的話，你能第一時間想到可以用MDC就夠了，也能裝一把逼?

本文涉及的程式碼已託管到碼雲，https://gitee.com/itwalking/slf4j-MDC.git，需要的可以下載啦。

記得點贊、轉發，多謝支援啦

之前整理的 redis 和 MQ 的知識點思維導圖分享給大家，2K+的小夥伴都領取了你還不快來領~

往期熱文：

歡迎關注我哦，謝謝大家的支援

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

相關文章