slf4j MDC使用
最近也是在项目代码里发现一个地方有个
MDC.put()
,忍不住好奇点了进去,于是知道了MDC这个东西,细研究一下,发现还真是个好东西。
MDC解决了什么问题
MDC全名Mapped Diagnostic Contexts,是slf4j提供的一个API,主要功能就是在多线程环境下进行日志调用链路的跟踪,比如在一次事务处理中,会经过多个处理的流程,为了定位问题方便,在每个流程中免不了打印一些日志信息。在线上环境中,最后打出来的日志是很多的,如何定位哪些信息是在同一个线程中打印的呢?MDC很优雅地解决了这个问题。其他的日志框架有没有这个功能我暂时没去研究,对于slf4j(现在应该都会优先用这个吧?),实现了MDC的有logback和log4j,这里暂时以logback为例,更详细的文档见这里
MDC的使用
MDC使用起来还是相当简单的,一个例子就搞定了。
首先配置日志配置文件logback.xml
<span style="color:#333333"><code><span style="color:#0000ff"><<span style="color:#0000ff">configuration</span>></span>
<span style="color:#0000ff"><<span style="color:#0000ff">appender</span> <span style="color:#ff0000">name</span>=<span style="color:#a31515">"STDOUT"</span> <span style="color:#ff0000">class</span>=<span style="color:#a31515">"ch.qos.logback.core.ConsoleAppender"</span>></span>
<span style="color:#0000ff"><<span style="color:#0000ff">encoder</span>></span>
<span style="color:#0000ff"><<span style="color:#0000ff">pattern</span>></span>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %X{txId} - %msg%n<span style="color:#0000ff"></<span style="color:#0000ff">pattern</span>></span>
<span style="color:#0000ff"></<span style="color:#0000ff">encoder</span>></span>
<span style="color:#0000ff"></<span style="color:#0000ff">appender</span>></span>
<span style="color:#0000ff"><<span style="color:#0000ff">root</span> <span style="color:#ff0000">level</span>=<span style="color:#a31515">"debug"</span>></span>
<span style="color:#0000ff"><<span style="color:#0000ff">appender-ref</span> <span style="color:#ff0000">ref</span>=<span style="color:#a31515">"STDOUT"</span>/></span>
<span style="color:#0000ff"></<span style="color:#0000ff">root</span>></span>
<span style="color:#0000ff"></<span style="color:#0000ff">configuration</span>></span></code></span>
为了输出很简单的一个配置注意有个占位符txId,这就是我们每次事务处理的id。现在我们模拟多个线程同时处理事务。定义了一次事务处理的流程。
<span style="color:#333333"><code><span style="color:#0000ff">public</span> <span style="color:#0000ff">class</span> <span style="color:#a31515">TxFlow</span> {
<span style="color:#0000ff">private</span> <span style="color:#0000ff">static</span> <span style="color:#0000ff">final</span> Logger LOGGER = LoggerFactory.getLogger(TxFlow.class);
<span style="color:#0000ff">private</span> <span style="color:#0000ff">void</span> <span style="color:#a31515">prepare</span>() {
LOGGER.info(<span style="color:#a31515">"prepare tx"</span>);
}
<span style="color:#0000ff">private</span> <span style="color:#0000ff">void</span> <span style="color:#a31515">handle</span>() {
LOGGER.info(<span style="color:#a31515">"handle tx"</span>);
<span style="color:#0000ff">try</span> {
Thread.sleep(<span style="color:#0000ff">new</span> Random().nextInt(4) * 1000);
} <span style="color:#0000ff">catch</span> (InterruptedException ignored) {
}
}
<span style="color:#0000ff">private</span> <span style="color:#0000ff">void</span> <span style="color:#a31515">submit</span>() {
LOGGER.info(<span style="color:#a31515">"submit tx"</span>);
}
<span style="color:#0000ff">public</span> <span style="color:#0000ff">void</span> <span style="color:#a31515">run</span>() {
prepare();
handle();
submit();
}
}</code></span>
对每一次事务处理,我们生成一个事务ID,并put到MDC中去。
<span style="color:#333333"><code><span style="color:#0000ff">public</span> <span style="color:#0000ff">class</span> <span style="color:#a31515">TxMDC</span> {
<span style="color:#0000ff">private</span> <span style="color:#0000ff">static</span> <span style="color:#0000ff">final</span> Logger LOGGER = LoggerFactory.getLogger(TxMDC.class);
<span style="color:#0000ff">public</span> <span style="color:#0000ff">static</span> <span style="color:#0000ff">void</span> <span style="color:#a31515">main</span>(String[] args) {
LOGGER.info(<span style="color:#a31515">"main thread start"</span>);
<span style="color:#0000ff">for</span> (<span style="color:#0000ff">int</span> i = 0; i < 5; i++) {
<span style="color:#0000ff">new</span> Thread(() -> {
MDC.put(<span style="color:#a31515">"txId"</span>, UUID.randomUUID().toString());
<span style="color:#0000ff">new</span> TxFlow().run();
}).start();
}
}
}</code></span>
得到输出如下,这样就很容易根据事务ID将一次事务中各个流程中的日志信息串联起来,便于后期的处理(比如查到一次事务的txId后grep一下txId就把整个处理流程中的日志信息串联起来了)。
<span style="color:#333333"><code>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</code></span>
MDC的实现原理
slf4j只提供了一个接口,具体的实现在logback和log4j中。不过从上面功能中,我们已经知道MDC记录了是线程上下文,聪明的你肯定已经想到了实现是基于ThreadLocal
,事实也如此,有兴趣继续研究代码我就不多说了。
许多年前 你有一双清澈的双眼
奔跑起来 像是一道春天的闪电想看遍这世界 去最遥远的远方
感觉有双翅膀 能飞越高山和海洋