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实现原理

MDC.java

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来做实现。

参考

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 159,015评论 4赞 362
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 67,262评论 1赞 292
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 108,727评论 0赞 243
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 43,986评论 0赞 205
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 52,363评论 3赞 287
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 40,610评论 1赞 219
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 31,871评论 2赞 312
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 30,582评论 0赞 198
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 34,297评论 1赞 242
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,551评论 2赞 246
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,053评论 1赞 260
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 28,385评论 2赞 253
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 33,035评论 3赞 236
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,079评论 0赞 8
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,841评论 0赞 195
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 35,648评论 2赞 274
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 35,550评论 2赞 270

推荐阅读更多精彩内容

  • Spring Cloud
    Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具（例如配置管理，服务发现，断路器，智...
    卡卡罗2017阅读 134,100评论 18赞 139
  • [翻译] logstash中logback的json编码器插件
    原文地址为 https://github.com/logstash/logstash-logback-encode...
    飞来来阅读 17,431评论 1赞 10
  • 镜铁山寻宝记
    镜铁和菱铁、褐铁、赤铁一样，是铁矿的一种，祁连山到了这一段，忽然就含有大量的镜铁矿，从而得了一个很写实的名字，就叫...
    马少军阅读 366评论 3赞 2
  • 治国五策
    尊贤使能，俊杰在位，则天下之士皆悦，而愿立于其朝矣；市，廛而不征，法而不廛，则天下之商皆悦，而愿藏于其市矣；关，讥...
    风月无情人暗换阅读 737评论 0赞 0