why?

一个web项目通常提供很多URL访问地址，

项目一般都是分层处理，例如Controller——>Service——>DAO。

如果想根据日志查看用户一次请求都走了哪些方法（多数是查错误）。

如果系统是多人访问,日志打印是无序的，想要串行拿到日志是大海捞针。

能通过一个字符串就能将一次请求调用了哪些方法按照顺序搜索出来就好了。

how?

Slf4j的MDC ( Mapped Diagnostic Contexts )专门为此需求而生。

MDC的基本原理是：

通过一个ThreadLocal保存设置的key值，在打印的时候从ThreadLocal中获取到打印出来。由此可知，如果一个请求中的某些方法调用是在另外的线程中执行，那MDC是获取不到该值的。

note 当前线程的子线程会继承其父线程中的MDC的内容，所以不用担心会话过程中，新创建的子线程无法追踪。

为什么最开始子线程会得到父线程MDC设置的内容?创建子线程的时候会调用init(ThreadGroup g, Runnable target, String name,long stackSize)方法，判断如果parent.inheritableThreadLocals不为null就调用createInheritedMap方法把父线程的ThreadLocal里保存的变量都加载到子线程的ThreadLocal中去。所以MDC类的静态变量mdcAdapter(LogbackMDCAdapter实现)中的copyOnInheritThreadLocal会得到父类MDC写入的内容，因为它用的是InheritableThreadLocal这个继承类。

底层代码

/*** This class hides and serves as a substitute for the underlying logging* system's MDC implementation.* * <p>* If the underlying logging system offers MDC functionality, then SLF4J's MDC,* i.e. this class, will delegate to the underlying system's MDC. Note that at* this time, only two logging systems, namely log4j and logback, offer MDC* functionality. For java.util.logging which does not support MDC,* {@link BasicMDCAdapter} will be used. For other systems, i.e. slf4j-simple* and slf4j-nop, {@link NOPMDCAdapter} will be used.** <p>* Thus, as a SLF4J user, you can take advantage of MDC in the presence of log4j,* logback, or java.util.logging, but without forcing these systems as* dependencies upon your users.* * <p>* For more information on MDC please see the <a* href="http://logback.qos.ch/manual/mdc.html">chapter on MDC</a> in the* logback manual.* * <p>* Please note that all methods in this class are static.* * @author Ceki G&uuml;lc&uuml;* @since 1.4.1*/
public class MDC {

/*** Basic MDC implementation, which can be used with logging systems that lack* out-of-the-box MDC support.** This code was initially inspired by  logback's LogbackMDCAdapter. However,* LogbackMDCAdapter has evolved and is now considerably more sophisticated.** @author Ceki Gulcu* @author Maarten Bosteels* @author Lukasz Cwik* * @since 1.5.0*/
public class BasicMDCAdapter implements MDCAdapter {private InheritableThreadLocal<Map<String, String>> inheritableThreadLocal = new InheritableThreadLocal<Map<String, String>>() {@Overrideprotected Map<String, String> childValue(Map<String, String> parentValue) {if (parentValue == null) {return null;}return new HashMap<String, String>(parentValue);}};/*** 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>* 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) {if (key == null) {throw new IllegalArgumentException("key cannot be null");}Map<String, String> map = inheritableThreadLocal.get();if (map == null) {map = new HashMap<String, String>();inheritableThreadLocal.set(map);}map.put(key, val);}

/*** This class extends <tt>ThreadLocal</tt> to provide inheritance of values* from parent thread to child thread: when a child thread is created, the* child receives initial values for all inheritable thread-local variables* for which the parent has values.  Normally the child's values will be* identical to the parent's; however, the child's value can be made an* arbitrary function of the parent's by overriding the <tt>childValue</tt>* method in this class.** <p>Inheritable thread-local variables are used in preference to* ordinary thread-local variables when the per-thread-attribute being* maintained in the variable (e.g., User ID, Transaction ID) must be* automatically transmitted to any child threads that are created.** @author  Josh Bloch and Doug Lea* @see     ThreadLocal* @since   1.2*/public class InheritableThreadLocal<T> extends ThreadLocal<T> {/*** Computes the child's initial value for this inheritable thread-local* variable as a function of the parent's value at the time the child* thread is created.  This method is called from within the parent* thread before the child is started.* <p>* This method merely returns its input argument, and should be overridden* if a different behavior is desired.** @param parentValue the parent thread's value* @return the child thread's initial value*/protected T childValue(T parentValue) {return parentValue;}

1 修改日志文件

只需要在日志配置文件的pattern中中添加一个{key},在请求方法入口设置一个key=某字符串，logger日志就能输出此字符串。logger的所有日志方法不需要做任何改动。如下所示。

<?xml version="1.0" encoding="UTF-8" ?>
<configuration><appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"><layout class="ch.qos.logback.classic.PatternLayout"><pattern>%d{ISO8601} [%thread] [%-5level] [%-10X{tracing_id}] %logger - %msg%n</pattern></layout></appender><!-- 文件输出日志 (文件大小策略进行文件输出，超过指定大小对文件备份)--><appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><file>/data/rec_loader/logs/rec_loader.log</file><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><fileNamePattern>/data/rec_loader/logs/rec_loader.log.%d{yyyy-MM-dd}.%d{hh-mm-ss}</fileNamePattern><maxHistory>7</maxHistory><totalSizeCap>100GB</totalSizeCap></rollingPolicy><layout class="ch.qos.logback.classic.PatternLayout"><!--** 改动在此处 tracing_id**--><Pattern>%d{ISO8601} [%thread] [%-5level] [%-10X{tracing_id}] %logger - %msg%n</Pattern></layout></appender><root level="info"><appender-ref ref="STDOUT"/><appender-ref ref="FILE"/></root></configuration>

2 增加拦截器(跨系统之间可用，通过增加header字段)

import java.util.Objects;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.RandomStringUtils;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;/* ** *    Starry Starry Night* *          __   __* *          \/---\/* *           ). .(* *          ( (") )* *           )   (* *          /     \* *         (       )``* *        ( \ /-\ / )* *         w'W   W'w* ** author   杨春炼* email    qdcccc@gmail.com* date     2018-08-18**/
@Slf4j
public class ResponseMetricsInterceptor extends HandlerInterceptorAdapter {private static final String TRACING_ID = "tracing_id";private static final String RESPONSE_TIME = "response_time";@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response,Object handler) throws Exception {String tracingId;//this judgement used for webs contextif (StringUtils.isBlank(request.getHeader(TRACING_ID))) {tracingId = RandomStringUtils.randomAlphanumeric(10);} else {tracingId = request.getHeader(TRACING_ID);}response.setHeader(TRACING_ID, tracingId);//add a start time in request attributerequest.setAttribute(RESPONSE_TIME, System.currentTimeMillis());MDC.put(TRACING_ID, tracingId);log.info("tracing.start.url={}", request.getServletPath());return super.preHandle(request, response, handler);}@Overridepublic void afterCompletion(HttpServletRequest request, HttpServletResponse response,Object handler, Exception ex) throws Exception {try {Object attribute = request.getAttribute(RESPONSE_TIME);Long timeStart = Long.valueOf(Objects.toString(attribute, "0"));long responseTime = System.currentTimeMillis() - timeStart;log.info("tracing.end.url={}, 消耗时间:{}ms", request.getServletPath(), responseTime);} catch (Exception ignored) {} finally {//prevent memory leakMDC.remove(TRACING_ID);MDC.clear();}super.afterCompletion(request, response, handler, ex);}

import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport;/* ** *    Starry Starry Night* *          __   __* *          \/---\/* *           ). .(* *          ( (") )* *           )   (* *          /     \* *         (       )``* *        ( \ /-\ / )* *         w'W   W'w* ** author   杨春炼* email    qdcccc@gmail.com* date     2018-08-18**/
@Configuration
public class InterceptorConfig extends WebMvcConfigurationSupport {@Overridepublic void addInterceptors(InterceptorRegistry registry) {registry.addInterceptor(new ResponseMetricsInterceptor()).addPathPatterns("/**");}
}

Effect

向自己的项目发起一次http请求

结果如下图(顺便打印了该次http请求的总耗时)

更专业的分布式链路追踪中间件？

可以自行搜索 SOFATracer，比较重，觉得一般企业没必要应用。