logback的MDC机制

logback的MDC机制

1. MDC 介绍：

​ MDC（Mapped Diagnostic Context，映射调试上下文），即将一些运行时的上下文数据通过logback打印出来，是 一种方便在多线程条件下记录日志的功能。和SiftingAppender一起，可以实现根据运行时的上下文数据，将日志保存到不同的文件中。

2. demo：

2.1 logback配置文件：logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder charset="UTF-8">
            <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level [%class:%line] -  %X{logFileName} %X{logSign} %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="FILE-INSERT" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <key>logFileName</key>
            <defaultValue>defName</defaultValue>
        </discriminator>
        <sift>
            <appender name="FILE-${logFileName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <File>
                    D:/temp/downloadLogs/${logFileName}/gps.log
                </File>
                <layout class="ch.qos.logback.classic.PatternLayout">
                    <pattern>%msg%n</pattern>
                </layout>
                <append>true</append>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <fileNamePattern>
                        D:/temp/downloadLogs/${logFileName}/gps-%d{yyyyMMdd}.log
                    </fileNamePattern>
                    <maxHistory>2</maxHistory>
                </rollingPolicy>
            </appender>
        </sift>
    </appender>

    <logger name="com.chelaile.log.insert" level = "INFO">
        <appender-ref ref="FILE-INSERT"/>
        <appender-ref ref="console"/>
    </logger>

</configuration>

2.2 写文件的线程：

package com.chelaile.log.insert;

import org.slf4j.MDC;

import java.util.Map;

public abstract class MdcRunnable implements Runnable {

    /**
     * 为了线程池中的线程在复用的时候也能获得父线程的MDC中的信息，
     * 子线程第一次初始化的时候没事，因为通过ThreadLocal
     * 已经可以获得MDC中的内容了
     */
    private final Map mdcContext = MDC.getCopyOfContextMap();
    //ExecutorService.execute(new Runnable())的时候，在Runnable构造的时候，用这个方法得到一个Map，保存起来，这时的context是父线程的。
    //然后在执行run方法的时候，放到MDC中去——子线程的context map中去

    @Override
    public final void run() {
        // 线程重用的时候，把父线程中的context map内容带入当前线程的context map中，
        // 因为线程已经初始化过了，不会像初始化时那样通过拷贝父线程ThreadLocal到子线程
        // 的ThreadLocal操作来完成线程间context map的传递。
        // 真正执行到这个run方法的时候，已经到了子线程中了，所以要在初始化的时候用
        // MDC.getCopyOfContextMap()来获得父线程contest map，那时候还在父线程域中
        if (mdcContext != null) {
            MDC.setContextMap(mdcContext);//有了这一步其实不用MDC.clear，因为这一步会将子线程中的context map重置为父线程的context map
//            //源代码：
//            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);
//            }
        }
        try {
            runWithMdc();
        } finally {
//            MDC.clear();//如果都是用new Thread方法建立的线程可以不用加，因为之后线程会消亡。
            //如果用ThreadPool线程池的话，线程是可以重用的，如果之前的线程的MDC内容没有清除掉的话，
            // 再次重线程池中获取到这个线程，会取出之前的数据(脏数据)，会导致一些不可预期的错误，
            // 所以当前线程结束后一定要清掉。
        }
    }

    protected abstract void runWithMdc();
}

package com.chelaile.log.insert;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.TimeUnit;

public class LogRunnable extends MdcRunnable {

    private volatile boolean flag = true;

    private static final Logger log = LoggerFactory.getLogger(LogRunnable.class);

    private String code;

    // 阻塞队列
    private LinkedBlockingQueue<String> queue = new LinkedBlockingQueue<>();

    public LogRunnable(String code) {
        this.code = code;
    }

    @Override
    protected void runWithMdc() {
        String str;
        System.out.println("code=" + code + ",启动,logFileName=" + MDC.get("logFileName"));
        while (flag || queue.size() > 0) {
            try {
                str = queue.poll(5, TimeUnit.SECONDS);
                if (str == null || "null".equals(str) || "".equals(str)) {
                    continue;
                }
            } catch (InterruptedException e) {
                e.printStackTrace();
                continue;
            }
            log.info(str);
            MDC.put("logFileName",code);
        }
        System.out.println("code=" + code + ",结束,logFileName=" + MDC.get("logFileName"));
    }

    public void close() {
        this.flag = false;
    }

    public void setQueue(String str) {
        queue.add(str);
    }

    public String getCode() {
        return code;
    }
}

2.3 测试代码：

package com.chelaile.test;

import com.chelaile.SpringStart;
import com.chelaile.log.insert.LogRunnable;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.MDC;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.*;

@RunWith(SpringJUnit4ClassRunner.class)
@SpringBootTest(classes = SpringStart.class)
public class LogRunnableTest {

    private Map<Integer, LogRunnable> logRunnableMap = new HashMap<>();

    @Test
    public void testLog() {
        ExecutorService logExecService = Executors.newFixedThreadPool(1);
        MDC.put("logFileName","默认");
        MDC.put("logSign","标记");

        for (int i = 0; i < 5; i++) {
            LogRunnable logRunnable = new LogRunnable("test" + i);
            logExecService.execute(logRunnable);
            logRunnableMap.put(i,logRunnable);
        }
        for (int i = 0; i < 5; i++) {
            LogRunnable logRunnable = logRunnableMap.get(i);
            logRunnable.setQueue("测试数据" + i);
            logRunnable.setQueue("我是测试" + i);
            logRunnable.setQueue("测试测试" + i);
            logRunnable.close();
        }
        while(true){} //测试的时候，不加  while(true){}  的话，由于主线程结束，日志没有写入文件线程就终止了
    }

}

2.4输出：

2.4.1控制台输出：

code=test0,启动,logFileName=默认
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  默认 标记 测试数据0
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test0 标记 我是测试0
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test0 标记 测试测试0
code=test0,结束,logFileName=test0
code=test1,启动,logFileName=默认
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  默认 标记 测试数据1
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test1 标记 我是测试1
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test1 标记 测试测试1
code=test1,结束,logFileName=test1
code=test2,启动,logFileName=默认
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  默认 标记 测试数据2
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test2 标记 我是测试2
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test2 标记 测试测试2
code=test2,结束,logFileName=test2
code=test3,启动,logFileName=默认
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  默认 标记 测试数据3
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test3 标记 我是测试3
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test3 标记 测试测试3
code=test3,结束,logFileName=test3
code=test4,启动,logFileName=默认
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  默认 标记 测试数据4
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test4 标记 我是测试4
2018-07-19 15:44:12 INFO  [com.chelaile.log.insert.LogRunnable:38] -  test4 标记 测试测试4
code=test4,结束,logFileName=test4

2.4.2生成的日志目录结构：

3.遇到的问题：

​ 第一次logback.xml文件没有配置layout，因为只想写入kafka中的数据，不想加多余的东西，导致测试内容没能写入文件，加上之后就OK了

<layout class="ch.qos.logback.classic.PatternLayout">
    <pattern>%msg%n</pattern>
</layout>

4. MDC分析 ：

Slf4j MDC ：

​ 对外接口，就是对参数进行校验，然后调用MDCAdapter的方法实现。

Logback MDC ：

​ LogbackMDCAdapter类实现MDCAdapter接口，实现 put、get、remove等方法。

​ copyOnThreadLocal：存储每个线程的多个变量

​ 当在logback.xml中配置了%X{key} 或 SiftingAppender的<discriminator>的<key>，在需要输出日志的时候，从MDC中获取对应的key值，然后append到日志字符串中或生成文件路径，然后输出。

5. ThreadLocal 实现分析：

​ 在每个线程Thread内部有一个ThreadLocal.ThreadLocalMap类型的成员变量threadLocals，这个threadLocals就是用来存储实际的变量副本的，键值为当前ThreadLocal变量，value为变量副本（即T类型的变量）。

/* ThreadLocal values pertaining to this thread. This map is maintained
 * by the ThreadLocal class. */
ThreadLocal.ThreadLocalMap threadLocals = null;

​ 初始时，在Thread里面，threadLocals为空，当通过ThreadLocal变量调用get()方法或者set()方法，就会对Thread类中的threadLocals进行初始化，并且以当前ThreadLocal变量为键值，以ThreadLocal要保存的副本变量为value，存到threadLocals。

ThreadLocal类：

    ThreadLocalMap getMap(Thread t) {
        return t.threadLocals;
    }
    
    void createMap(Thread t, T firstValue) {
        t.threadLocals = new ThreadLocalMap(this, firstValue);
    }
    
    public void set(T value) {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null)
            map.set(this, value);//key用this，是因为同一个线程中如果有多个ThreadLocal，都会存储在该map中
        else
            createMap(t, value);
    }

    public T get() {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null) {
            ThreadLocalMap.Entry e = map.getEntry(this);
            if (e != null) {
                @SuppressWarnings("unchecked")
                T result = (T)e.value;
                return result;
            }
        }
        return setInitialValue();
    }

    private T setInitialValue() {
        T value = initialValue();
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null)
            map.set(this, value);
        else
            createMap(t, value);
        return value;
    }

ThreadLocal总结：

1.实际的通过ThreadLocal创建的副本是存储在每个线程自己的threadLocals中的；

2.为何threadLocals的类型ThreadLocalMap的键值为ThreadLocal对象，因为每个线程中可有多个threadLocal变量