slf4j MDC使用

最近也是在項目代碼里發現一個地方有個MDC.put()，忍不住好奇點了進去，於是知道了MDC這個東西，細研究一下，發現還真是個好東西。

MDC解決了什么問題

MDC全名Mapped Diagnostic Contexts，是slf4j提供的一個API，主要功能就是在多線程環境下進行日志調用鏈路的跟蹤，比如在一次事務處理中，會經過多個處理的流程，為了定位問題方便，在每個流程中免不了打印一些日志信息。在線上環境中，最后打出來的日志是很多的，如何定位哪些信息是在同一個線程中打印的呢？MDC很優雅地解決了這個問題。其他的日志框架有沒有這個功能我暫時沒去研究，對於slf4j（現在應該都會優先用這個吧？），實現了MDC的有logback和log4j，這里暫時以logback為例，更詳細的文檔見這里

MDC的使用

MDC使用起來還是相當簡單的，一個例子就搞定了。
首先配置日志配置文件logback.xml

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %X{txId} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

為了輸出很簡單的一個配置注意有個占位符txId，這就是我們每次事務處理的id。現在我們模擬多個線程同時處理事務。定義了一次事務處理的流程。

public class TxFlow {
    private static final Logger LOGGER = LoggerFactory.getLogger(TxFlow.class);

    private void prepare() {
        LOGGER.info("prepare tx");
    }

    private void handle() {
        LOGGER.info("handle tx");
        try {
            Thread.sleep(new Random().nextInt(4) * 1000);
        } catch (InterruptedException ignored) {
        }
    }

    private void submit() {
        LOGGER.info("submit tx");
    }

    public void run() {
        prepare();
        handle();
        submit();
    }
}

對每一次事務處理，我們生成一個事務ID，並put到MDC中去。

public class TxMDC {
    private static final Logger LOGGER = LoggerFactory.getLogger(TxMDC.class);

    public static void main(String[] args) {
        LOGGER.info("main thread start");
        for (int i = 0; i < 5; i++) {
            new Thread(() -> {
                MDC.put("txId", UUID.randomUUID().toString());
                new TxFlow().run();
            }).start();
        }
    }
}

得到輸出如下，這樣就很容易根據事務ID將一次事務中各個流程中的日志信息串聯起來，便於后期的處理（比如查到一次事務的txId后grep一下txId就把整個處理流程中的日志信息串聯起來了）。

13:20:21.581 [main] INFO  i.d.l.TxMDC txId=主線程ID - main thread start
13:20:22.050 [Thread-1] INFO  i.d.l.TxFlow txId=c4bd7356-b932-4571-bbad-d450e90de821 - prepare tx
13:20:22.050 [Thread-1] INFO  i.d.l.TxFlow txId=c4bd7356-b932-4571-bbad-d450e90de821 - handle tx
13:20:22.050 [Thread-2] INFO  i.d.l.TxFlow txId=9ee129de-0dfe-4086-9267-e6868e1478b0 - prepare tx
13:20:22.050 [Thread-2] INFO  i.d.l.TxFlow txId=9ee129de-0dfe-4086-9267-e6868e1478b0 - handle tx
13:20:22.052 [Thread-3] INFO  i.d.l.TxFlow txId=7971563a-2807-4e1f-bbd9-639a090b5689 - prepare tx
13:20:22.053 [Thread-3] INFO  i.d.l.TxFlow txId=7971563a-2807-4e1f-bbd9-639a090b5689 - handle tx
13:20:22.053 [Thread-4] INFO  i.d.l.TxFlow txId=5c5656c4-bc7a-4277-be25-2269aee0b54e - prepare tx
13:20:22.053 [Thread-4] INFO  i.d.l.TxFlow txId=5c5656c4-bc7a-4277-be25-2269aee0b54e - handle tx
13:20:22.054 [Thread-0] INFO  i.d.l.TxFlow txId=ebaa0082-1a19-450d-ba71-679510a2fa92 - prepare tx
13:20:22.054 [Thread-0] INFO  i.d.l.TxFlow txId=ebaa0082-1a19-450d-ba71-679510a2fa92 - handle tx
13:20:22.082 [Thread-1] INFO  i.d.l.TxFlow txId=c4bd7356-b932-4571-bbad-d450e90de821 - submit tx
13:20:23.055 [Thread-0] INFO  i.d.l.TxFlow txId=ebaa0082-1a19-450d-ba71-679510a2fa92 - submit tx
13:20:24.050 [Thread-2] INFO  i.d.l.TxFlow txId=9ee129de-0dfe-4086-9267-e6868e1478b0 - submit tx
13:20:25.054 [Thread-3] INFO  i.d.l.TxFlow txId=7971563a-2807-4e1f-bbd9-639a090b5689 - submit tx
13:20:25.055 [Thread-4] INFO  i.d.l.TxFlow txId=5c5656c4-bc7a-4277-be25-2269aee0b54e - submit tx

MDC的實現原理

slf4j只提供了一個接口，具體的實現在logback和log4j中。不過從上面功能中，我們已經知道MDC記錄了是線程上下文，聰明的你肯定已經想到了實現是基於ThreadLocal，事實也如此，有興趣繼續研究代碼我就不多說了。