Slf4j.MDC原始碼分析：以及利用MDC和AOP進行日誌追蹤
阿新 • • 發佈：2018-12-17
在 Java 開發中，日誌的列印輸出是必不可少的，Slf4j + LogBack 的組合是最通用的方式。但是，在分散式系統中，各種無關日誌穿行其中，導致我們可能無法直接定位整個操作流程。因此，我們可能需要對一個使用者的操作流程進行歸類標記，既在其日誌資訊上新增一個唯一標識，比如使用執行緒+時間戳，或者使用者身份標識等；從大量日誌資訊中grep出某個使用者的操作流程。
MDC ( Mapped Diagnostic Contexts )
- 顧名思義，其目的是為了便於我們診斷線上問題而出現的方法工具類。雖然，Slf4j 是用來適配其他的日誌具體實現包的，但是針對 MDC功能，目前只有logback 以及 log4j 支援。
- MDC 主要用於儲存上下文，區分不同的請求來源。
- MDC 管理是按執行緒劃分，並且子執行緒會自動繼承母執行緒的上下文。
MDC使用方式：
一般，我們在程式碼中，只需要將指定的值put到執行緒上下文的Map中，然後，在對應的地方使用 get方法獲取對應的值。此外，對於一些執行緒池使用的應用場景，可能我們在最後使用結束時，需要呼叫clear方法來清洗將要丟棄的資料。
MDC簡單使用案例
Tip:此處先舉例一個簡單的案例，待到對MDC遠離分析完畢，再來一個專案實戰的案例。
1、在MDC中新增標識：
public class LogTest {
private static final Logger logger = 2、在logback.xml中配置日誌格式： （關鍵點在於：traceId:[%X{mdc_trace_id}]）
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
.....
< 3、輸出結果：
[18-10-26.10:43:00.281] - traceId:[0000000000001] - 這是一條測試日誌。
MDC原始碼探索
MDC 的功能實現很簡單，就是線上程上下文中，維護一個 Map<String,String> 屬性來支援日誌輸出的時候，當我們在配置檔案logback.xml 中配置了%X{key}，則後臺日誌打印出對應的 key 的值。
其實對於MDC，可以簡單將其理解為一個執行緒級的容器。對於標識的操作其實也很簡單，大部分就是put、get和clear。
先來看看 org.slf4j.MDC
//
// Source code recreated from a .class file by IntelliJ IDEA
// (powered by Fernflower decompiler)
//
package org.slf4j;
import java.io.Closeable;
import java.util.Map;
import org.slf4j.helpers.NOPMDCAdapter;
import org.slf4j.helpers.Util;
import org.slf4j.impl.StaticMDCBinder;
import org.slf4j.spi.MDCAdapter;
public class MDC {
static MDCAdapter mdcAdapter;
除了put\get\remove\clear外，其他方法省略....
public static void put(String key, String val) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key parameter cannot be null");
} else if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
} else {
mdcAdapter.put(key, val);
}
}
public static String get(String key) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key parameter cannot be null");
} else if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
} else {
return mdcAdapter.get(key);
}
}
public static void remove(String key) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key parameter cannot be null");
} else if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
} else {
mdcAdapter.remove(key);
}
}
public static void clear() {
if (mdcAdapter == null) {
throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
} else {
mdcAdapter.clear();
}
}
static {
try {
mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();
} catch (NoClassDefFoundError var2) {
mdcAdapter = new NOPMDCAdapter();
String msg = var2.getMessage();
if (msg == null || msg.indexOf("StaticMDCBinder") == -1) {
throw var2;
}
Util.report("Failed to load class \"org.slf4j.impl.StaticMDCBinder\".");
Util.report("Defaulting to no-operation MDCAdapter implementation.");
Util.report("See http://www.slf4j.org/codes.html#no_static_mdc_binder for further details.");
} catch (Exception var3) {
Util.report("MDC binding unsuccessful.", var3);
}
}
}
觀察上面的方法，各個方法都是在對 mdcAdapter變數進行操作。
mdcAdapter.put(key, val);
mdcAdapter.get(key);
mdcAdapter.remove(key);
mdcAdapter.clear();
檢視mdcAdapter變數的初始化過程：
mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();
檢視：
StaticMDCBinder.java
public class StaticMDCBinder {
public static final StaticMDCBinder SINGLETON = new StaticMDCBinder();
private StaticMDCBinder() {
}
public MDCAdapter getMDCA() {
return new LogbackMDCAdapter();
}
public String getMDCAdapterClassStr() {
return LogbackMDCAdapter.class.getName();
}
}
這樣，就能找到我們容器真正的宿主mdcAdapter其實是類：LogbackMDCAdapter，檢視其原始碼：
//
// Source code recreated from a .class file by IntelliJ IDEA
// (powered by Fernflower decompiler)
//
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 final class LogbackMDCAdapter implements MDCAdapter {
final InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal();
private static final int WRITE_OPERATION = 1;
private static final int READ_OPERATION = 2;
final ThreadLocal<Integer> lastOperation = new ThreadLocal();
public void put(String key, String val) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key cannot be null");
} else {
Map<String, String> oldMap = (Map)this.copyOnInheritThreadLocal.get();
Integer lastOp = this.getAndSetLastOperation(1);
if (!this.wasLastOpReadOrNull(lastOp) && oldMap != null) {
oldMap.put(key, val);
} else {
Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
}
}
}
public void remove(String key) {
if (key != null) {
Map<String, String> oldMap = (Map)this.copyOnInheritThreadLocal.get();
if (oldMap != null) {
Integer lastOp = this.getAndSetLastOperation(1);
if (this.wasLastOpReadOrNull(lastOp)) {
Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
newMap.remove(key);
} else {
oldMap.remove(key);
}
}
}
}
public void clear() {
this.lastOperation.set(1);
this.copyOnInheritThreadLocal.remove();
}
public String get(String key) {
Map<String, String> map = this.getPropertyMap();
return map != null && key != null ? (String)map.get(key) : null;
}
}
從上面的原始碼可以得知，之所以能保證不同執行緒都存在自己的標識，原因在於ThreadLocal。
在 ThreadLocal 中，每個執行緒都擁有了自己獨立的一個變數，執行緒間不存在共享競爭發生，並且它們也能最大限度的由CPU排程，併發執行。
對於ThreadLocal的介紹，可以參考我的另一篇部落格《深入理解ThreadLocal的原理和記憶體洩漏問題》，此處不再贅述。
但是，ThreadLocal有一個問題，就是它只保證在同一個執行緒間共享變數，也就是說如果這個執行緒起了一個新執行緒，那麼新執行緒是不會得到父執行緒的變數資訊的。
因此，為了保證子執行緒可以擁有父執行緒的某些變數檢視，JDK提供了一個數據結構，InheritableThreadLocal。其原始碼如下：
public class InheritableThreadLocal<T> extends ThreadLocal<T> {
/**
* 根據建立子執行緒時父執行緒的值，計算該可繼承執行緒本地變數的子執行緒的初始值。
*在啟動子之前，從父執行緒中呼叫此方法。
*/
protected T childValue(T parentValue) {
return parentValue;
}
/**
* Get the map associated with a ThreadLocal.
*
* @param t the current thread
*/
ThreadLocalMap getMap(Thread t) {
return t.inheritableThreadLocals;
}
/**
* Create the map associated with a ThreadLocal.
*
* @param t the current thread
* @param firstValue value for the initial entry of the table.
*/
void createMap(Thread t, T firstValue) {
t.inheritableThreadLocals = new ThreadLocalMap(this, firstValue);
}
}
MDC存放變數的來龍去脈基本從上面原始碼都可以理清楚了，那麼對於logback.xml中是如何獲取到MDC的變數呢？
%X{mdc_key}
同樣，logback.xml配置檔案支援了多種格式的日誌輸出，比如%highlight、%d等等，這些標誌，在PatternLayout.java中維護。
PatternLayout.java:
public class PatternLayout extends PatternLayoutBase<ILoggingEvent> {
public static final Map<String, String> defaultConverterMap = new HashMap();
public static final String HEADER_PREFIX = "#logback.classic pattern: ";
public PatternLayout() {
this.postCompileProcessor = new EnsureExceptionHandling();
}
public Map<String, String> getDefaultConverterMap() {
return defaultConverterMap;
}
public String doLayout(ILoggingEvent event) {
return !this.isStarted() ? "" : this.writeLoopOnConverters(event);
}
protected String getPresentationHeaderPrefix() {
return "#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());
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());
defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
defaultConverterMap.put("line", LineOfCallerConverter.class.getName());
defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
defaultConverterMap.put("file", FileOfCallerConverter.class.getName());
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