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变量