Slf4j MDC機制

MDC 簡介

MDC ( Mapped Diagnostic Contexts )，它是一個線程安全的存放診斷日誌的容器。

Logback設計的一個目標之一是對分佈式應用系統的審計和調試。在如今的分佈式系統中，須要同時處理不少的請求。如何來很好的區分日誌究竟是那個請求輸出的呢？咱們能夠爲每個請求生一個logger，可是這樣子最產生大量的資源浪費，而且隨着請求的增多這種方式會將服務器資源消耗殆盡，因此這種方式並不推薦。

一種更加輕量級的實現是使用MDC機制，在處理請求前將請求的惟一標示放到MDC容器中如sessionId，這個惟一標示會隨着日誌一塊兒輸出，以此來區分該條日誌是屬於那個請求的。並在請求處理完成以後清除MDC容器。

下面是MDC對外提供的方法，也能夠經過MDC javadocs查看全部方法。

package org.slf4j;

public class MDC {
  // 將一個K-V的鍵值對放到容器，實際上是放到當前線程的ThreadLocalMap中
  public static void put(String key, String val);

  // 根據key在當前線程的MDC容器中獲取對應的值
  public static String get(String key);

  // 根據key移除容器中的值
  public static void remove(String key);

  // 清空當前線程的MDC容器
  public static void clear();
}

簡單的例子

Example 7.1: Basic MDC usage ( logback-examples/src/main/java/chapters/mdc/SimpleMDC.java)

package com.xiaolyuh;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class SimpleMDC {
    public static void main(String[] args) throws Exception {

        // You can put values in the MDC at any time. Before anything else
        // we put the first name
        MDC.put("first", "Dorothy");

        Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
        // We now put the last name
        MDC.put("last", "Parker");

        // The most beautiful two words in the English language according
        // to Dorothy Parker:
        logger.info("Check enclosed.");
        logger.debug("The most beautiful two words in English.");

        MDC.put("first", "Richard");
        MDC.put("last", "Nixon");
        logger.info("I am not a crook.");
        logger.info("Attributed to the former US president. 17 Nov 1973.");
    }

}

Logback配置：

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
  <layout>
    <Pattern>%X{first} %X{last} - %m%n</Pattern>
  </layout> 
</appender>

輸出日誌：

Dorothy Parker - Check enclosed.
Dorothy Parker - The most beautiful two words in English.
Richard Nixon - I am not a crook.
Richard Nixon - Attributed to the former US president. 17 Nov 1973.

1. 在日誌模板logback.xml 中，使用 %X{ }來佔位，替換到對應的 MDC 中 key 的值。一樣，logback.xml配置文件支持了多種格式的日誌輸出，好比%highlight、%d等等，這些標誌，在PatternLayout.java中維護。
2. MDC的容器中的key能夠屢次賦值，最後一次的賦值會覆蓋上一次的值。

PatternLayout :

public class PatternLayout extends PatternLayoutBase<ILoggingEvent> {

    public static final Map<String, String> defaultConverterMap = new HashMap<String, String>();
    public static final String HEADER_PREFIX = "#logback.classic pattern: ";

    static {
        defaultConverterMap.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
        // 按照{}配置輸出時間
        defaultConverterMap.put("d", DateConverter.class.getName());
        defaultConverterMap.put("date", DateConverter.class.getName());
        // 輸出應用啓動到日誌時間觸發時候的毫秒數
        defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
        defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());
        // 輸出日誌級別的信息
        defaultConverterMap.put("level", LevelConverter.class.getName());
        defaultConverterMap.put("le", LevelConverter.class.getName());
        defaultConverterMap.put("p", LevelConverter.class.getName());
        // 輸出產生日誌事件的線程名
        defaultConverterMap.put("t", ThreadConverter.class.getName());
        defaultConverterMap.put("thread", ThreadConverter.class.getName());
        // 輸出產生log事件的原點的日誌名=咱們建立logger的時候設置的
        defaultConverterMap.put("lo", LoggerConverter.class.getName());
        defaultConverterMap.put("logger", LoggerConverter.class.getName());
        defaultConverterMap.put("c", LoggerConverter.class.getName());
        // 輸出 提供日誌事件的對應的應用信息
        defaultConverterMap.put("m", MessageConverter.class.getName());
        defaultConverterMap.put("msg", MessageConverter.class.getName());
        defaultConverterMap.put("message", MessageConverter.class.getName());
        // 輸出調用方發佈日誌事件的完整類名
        defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
        defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());
        // 輸出發佈日誌請求的方法名
        defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
        defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());
        // 輸出log請求的行數
        defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
        defaultConverterMap.put("line", LineOfCallerConverter.class.getName());
        // 輸出發佈日誌請求的java源碼的文件名
        defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
        defaultConverterMap.put("file", FileOfCallerConverter.class.getName());
        // 輸出和發佈日誌事件關聯的線程的MDC
        defaultConverterMap.put("X", MDCConverter.class.getName());
        defaultConverterMap.put("mdc", MDCConverter.class.getName());
        // 輸出和日誌事件關聯的異常的堆棧信息
        defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
        defaultConverterMap.put("exception", ThrowableProxyConverter.class
                .getName());
        defaultConverterMap.put("rEx", RootCauseFirstThrowableProxyConverter.class.getName());
        defaultConverterMap.put("rootException", RootCauseFirstThrowableProxyConverter.class
                .getName());
        defaultConverterMap.put("throwable", ThrowableProxyConverter.class
                .getName());
        // 和上面同樣，此外增長類的包信息
        defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
        defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class
                .getName());
        defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class
                .getName());
        // 當咱們想不輸出異常信息時，使用這個。其僞裝處理異常，其實無任何輸出
        defaultConverterMap.put("nopex", NopThrowableInformationConverter.class
                .getName());
        defaultConverterMap.put("nopexception",
                NopThrowableInformationConverter.class.getName());
        // 輸出在類附加到日誌上的上下文名字. 
        defaultConverterMap.put("cn", ContextNameConverter.class.getName());
        defaultConverterMap.put("contextName", ContextNameConverter.class.getName());
        // 輸出產生日誌事件的調用者的位置信息
        defaultConverterMap.put("caller", CallerDataConverter.class.getName());
        // 輸出和日誌請求關聯的marker
        defaultConverterMap.put("marker", MarkerConverter.class.getName());
        // 輸出屬性對應的值，通常爲System.properties中的屬性
        defaultConverterMap.put("property", PropertyConverter.class.getName());
        // 輸出依賴系統的行分隔符
        defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
        // 相關的顏色格式設置
        defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
        defaultConverterMap.put("red", RedCompositeConverter.class.getName());
        defaultConverterMap.put("green", GreenCompositeConverter.class.getName());
        defaultConverterMap.put("yellow", YellowCompositeConverter.class.getName());
        defaultConverterMap.put("blue", BlueCompositeConverter.class.getName());
        defaultConverterMap.put("magenta", MagentaCompositeConverter.class.getName());
        defaultConverterMap.put("cyan", CyanCompositeConverter.class.getName());
        defaultConverterMap.put("white", WhiteCompositeConverter.class.getName());
        defaultConverterMap.put("gray", GrayCompositeConverter.class.getName());
        defaultConverterMap.put("boldRed", BoldRedCompositeConverter.class.getName());
        defaultConverterMap.put("boldGreen", BoldGreenCompositeConverter.class.getName());
        defaultConverterMap.put("boldYellow", BoldYellowCompositeConverter.class.getName());
        defaultConverterMap.put("boldBlue", BoldBlueCompositeConverter.class.getName());
        defaultConverterMap.put("boldMagenta", BoldMagentaCompositeConverter.class.getName());
        defaultConverterMap.put("boldCyan", BoldCyanCompositeConverter.class.getName());
        defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
        defaultConverterMap.put("highlight", HighlightingCompositeConverter.class.getName());
    }
}

Notes：日誌模板配置，使用 %爲前綴讓解析器識別特殊輸出模式，而後以{}後綴結尾，內部指定相應的參數設置。

使用切面

在處理請求前將請求的惟一標示放到MDC容器中如sessionId，這個惟一標示會隨着日誌一塊兒輸出，以此來區分該條日誌是屬於那個請求的。這個咱們可使用Advanced來實現，可使用filter，interceptor等。

Interceptor

能夠參考篇文章Logback 快速定位用戶在一次請求中的全部日誌。

MDCInsertingServletFilter

這是Logback提供的一個filter，他會將一些請求信息放到MDC容器中，這個filter最好放到配置編碼的filter以後。如下是詳細的key：

| MDC key | MDC value | --|-- | req.remoteHost | as returned by the getRemoteHost() method | | req.xForwardedFor | value of the "X-Forwarded-For" header | | req.method | as returned by getMethod() method | | req.requestURI | as returned by getRequestURI() method | | req.requestURL | as returned by getRequestURL() method | | req.queryString | as returned by getQueryString() method | | req.userAgent | value of the "User-Agent" header |

使用配置：須要保證filter在須要使用的到該MDC的其餘filter以前。

<filter>
 <filter-name>MDCInsertingServletFilter</filter-name>
 <filter-class>
   ch.qos.logback.classic.helpers.MDCInsertingServletFilter
 </filter-class>
</filter>
<filter-mapping>
 <filter-name>MDCInsertingServletFilter</filter-name>
 <url-pattern>/*</url-pattern>
</filter-mapping>

應用key：

%X{req.remoteHost} %X{req.requestURI}%n%d - %m%n

管理每一個線程的MDC容器

咱們在主線程上，新起一個子線程，並由 java.util.concurrent.Executors來執行它時，在早期的版本中子線程能夠直接自動繼承父線程的MDC容器中的內容，由於MDC在早期版本中使用的是InheritableThreadLocal來做爲底層實現。可是因爲性能問題被取消了，最後仍是使用的是ThreadLocal來做爲底層實現。這樣子線程就不能直接繼承父線程的MDC容器。

因此，Logback官方建議咱們在父線程新建子線程以前調用MDC.getCopyOfContextMap()方法將MDC內容取出來傳給子線程，子線程在執行操做前先調用MDC.setContextMap()方法將父線程的MDC內容設置到子線程。

Slf4j MDC實現原理

Slf4j 的實現原則就是調用底層具體實現類，好比logback,logging等包；而不會去實現具體的輸出打印等操做。這裏使用了裝飾者模式，看源碼就能看出來，全部的方法都是在對mdcAdapter 這個屬性進行操做。因此實現核心是MDCAdapter類。

MDCAdapter

MDCAdapter只是定義了一個接口，具體實現由子類完成，源碼以下：

public interface MDCAdapter {
    public void put(String key, String val);

    public String get(String key);

    public void remove(String key);

    public void clear();

    public Map<String, String> getCopyOfContextMap();

    public void setContextMap(Map<String, String> contextMap);
}

它有三個實現類，BasicMDCAdapter、LogbackMDCAdapter，NOPMDCAdapter。Logback使用的是LogbackMDCAdapter。

LogbackMDCAdapter

package ch.qos.logback.classic.util;

import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
import java.util.Set;

import org.slf4j.spi.MDCAdapter;

public class LogbackMDCAdapter implements MDCAdapter {

    final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();

    private static final int WRITE_OPERATION = 1;
    private static final int MAP_COPY_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() == MAP_COPY_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);
            }
        }

        copyOnThreadLocal.set(newMap);
        return newMap;
    }

    /**
     * Put a context value (the <code>val</code> parameter) as identified with the
     * <code>key</code> parameter into the current thread's context map. Note that
     * contrary to log4j, the <code>val</code> parameter can be null.
     * <p/>
     * <p/>
     * If the current thread does not have a context map it is created as a side
     * effect of this call.
     *
     * @throws IllegalArgumentException in case the "key" parameter is null
     */
    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();
        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);
        }
    }

    /**
     * Remove the the context identified by the <code>key</code> parameter.
     * <p/>
     */
    public void remove(String key) {
        if (key == null) {
            return;
        }
        Map<String, String> oldMap = copyOnThreadLocal.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);
        }
    }

    /**
     * Clear all entries in the MDC.
     */
    public void clear() {
        lastOperation.set(WRITE_OPERATION);
        copyOnThreadLocal.remove();
    }

    /**
     * Get the context identified by the <code>key</code> parameter.
     * <p/>
     */
    public String get(String key) {
        final Map<String, String> map = copyOnThreadLocal.get();
        if ((map != null) && (key != null)) {
            return map.get(key);
        } else {
            return null;
        }
    }

    /**
     * Get the current thread's MDC as a map. This method is intended to be used
     * internally.
     */
    public Map<String, String> getPropertyMap() {
        lastOperation.set(MAP_COPY_OPERATION);
        return copyOnThreadLocal.get();
    }

    /**
     * Returns the keys in the MDC as a {@link Set}. The returned value can be
     * null.
     */
    public Set<String> getKeys() {
        Map<String, String> map = getPropertyMap();

        if (map != null) {
            return map.keySet();
        } else {
            return null;
        }
    }

    /**
     * Return a copy of the current thread's context map. Returned value may be
     * null.
     */
    public Map<String, String> getCopyOfContextMap() {
        Map<String, String> hashMap = copyOnThreadLocal.get();
        if (hashMap == null) {
            return null;
        } else {
            return new HashMap<String, String>(hashMap);
        }
    }

    public void setContextMap(Map<String, String> contextMap) {
        lastOperation.set(WRITE_OPERATION);

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

        // the newMap replaces the old one for serialisation's sake
        copyOnThreadLocal.set(newMap);
    }
}

final ThreadLocal<Integer> lastOperation = new ThreadLocal<Integer>();

經過這段代碼，咱們能夠看到底層最終是使用的是ThreadLocal來作實現。

參考

• https://logback.qos.ch/manual/mdc.html
• http://www.javashuo.com/article/p-ojyigbli-hd.html
• https://ketao1989.github.io/2015/04/29/LogBack-Implemention-And-Slf4j-Mdc/#%E8%BE%93%E5%87%BA%E6%97%A5%E5%BF%97%E6%A8%A1%E6%9D%BF%E8%A7%A3%E6%9E%90