ThreadLocal应用之MDC

ThreadLocal应用之MDC

MDC全称Mapped Diagnositc Context,是slf4j中的一个类,这个类的姐姐NDC(Nested Diagnostic Context)是log4j的一个类.

NDC采用栈的机制存储上下文,是线程独立的,子线程会从父线程拷贝上下文。

MDC采用Map的方式存储上下文,是线程独立的,子线程会从父线程拷贝上下文。这里主要针对MDC应用描述。

为什么说MDC

在设计分布式监控系统时,需要对系统中的链路信息按照上下文方式进行存储,并且时线程独立的,这个需求和MDC极为相似,同时带来了另外一个问题,监控系统的信息收集如果使用logback方式,则信息如何很好的切入到logback打印出来。

  1. 自己定义一个基于线程独立的ThreadLocal类,同时在各个点对信息进行增删改,在某一个重要的里程碑点,进行log入盘
  2. 直接将信息写入到MDC,由logback负责打印MDC内部的信息,这里刚好整个后续环节都交给logback直接处理了,免除了大量的开发环节,针对中小系统是个不错的选择

MDC初体验

首先看看MDC类的说明

1
2
3
4
5
6
7
8
9
public class MDC {
//Put a context value as identified by key into the current thread's context map.
public static void put(String key, String val);
//Get the context identified by the key parameter.
public static String get(String key);
//Remove the context identified by the key parameter.
public static void remove(String key);
//Clear all entries in the MDC.
public static void clear(); }

再简单撸一把

1
2
3
4
5
6
7
public class LogTest {
private static final Logger logger = LoggerFactory.getLogger(LogTest.class);
public static void main(String[] args) {
MDC.put("THREAD_ID", String.valueOf(Thread.currentThread().getId())); logger.info("纯字符串信息的info级别日志");
}
}

假设这是一次SpringMVC请求,在拦截器中开始调用一次MDC.put,写入本次调用的traceId,在拦截器结束,再一次MDC.get,拿到开始的时间和本次时间,同时得到运行时间+返回的结果status是200,还是4xx,5xx,再put一次,最后交给log.info打印出来

logback.xml片段,即可输出THREAD_ID的值,具体请参考logback的pattern源码对默认格式和自定义格式的补充

1
<pattern>[%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5p) %logger.%M(%F:%L)] %X{THREAD_ID} %msg%n</pattern>

ThreadLocal和MDC

在代码开发中,经常使用 ThreadLocal来保证在同一个线程中共享变量。在 ThreadLocal 中,每个线程都拥有了自己独立的一个变量,线程间不存在共享竞争发生,并且它们也能最大限度的由CPU调度,并发执行。

但是,ThreadLocal有一个问题,就是它只保证在同一个线程间共享变量,也就是说如果这个线程起了一个新线程,那么新线程是不会得到父线程的变量信息的。因此,为了保证子线程可以拥有父线程的某些变量视图,JDK提供了一个数据结构,InheritableThreadLocal

看一下java中的InheritableThreadLocal说明

该类扩展了 ThreadLocal,为子线程提供从父线程那里继承的值:在创建子线程时,子线程会接收所有可继承的线程局部变量的初始值,以获得父线程所具有的值。通常,子线程的值与父线程的值是一致的;但是,通过重写这个类中的 childValue 方法,子线程的值可以作为父线程值的一个任意函数。

考虑一个现实存在的问题,当SpringMVC拦截的请求中存在一个异步外发短信的功能,如果在链路信息中记录该外发信息的请求信息,这是一个典型的主线程调用子线程的案例,这个时候InheritableThreadLocal派上用场了。

从slf4j中看MDC类,整个实现都相对比较简单(因为一直使用logback,所以log4j略过),Logback 中基于 MDC 实现了LogbackMDCAdapter 类。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
/**
* A <em>Mapped Diagnostic Context</em>, or MDC in short, is an instrument for
* distinguishing interleaved log output from different sources. Log output is
* typically interleaved when a server handles multiple clients
* near-simultaneously.
* <p/>
* <b><em>The MDC is managed on a per thread basis</em></b>. A child thread
* automatically inherits a <em>copy</em> of the mapped diagnostic context of
* its parent.
* <p/>
* <p/>
* For more information about MDC, please refer to the online manual at
* http://logback.qos.ch/manual/mdc.html
*
* @author Ceki G&uuml;lc&uuml;
*/
public class LogbackMDCAdapter implements MDCAdapter {
// The internal map is copied so as
// We wish to avoid unnecessarily copying of the map. To ensure
// efficient/timely copying, we have a variable keeping track of the last
// operation. A copy is necessary on 'put' or 'remove' but only if the last
// operation was a 'get'. Get operations never necessitate a copy nor
// successive 'put/remove' operations, only a get followed by a 'put/remove'
// requires copying the map.
// See http://jira.qos.ch/browse/LOGBACK-620 for the original discussion.
// We no longer use CopyOnInheritThreadLocal in order to solve LBCLASSIC-183
// Initially the contents of the thread local in parent and child threads
// reference the same map. However, as soon as a thread invokes the put()
// method, the maps diverge as they should.
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);
}
}

在上面的代码中,write操作即put会去修改 lastOperation ,而get操作则不会。这样就保证了,只会在第一次写时复制。

关于logback打印

logback打印做的最主要的工作就是根据定义的logback.xml定义的各种参数和格式,按照logback中定义好的格式和Converter对应关系进行输出打印,这里就不详细讨论,详细可以阅读下logback源码PatternLayout类,还可以自定义格式和Coverter打印出想要的输出效果