利用Slf4j的MDC跟踪方法调用链

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>>() {
        @Override
        protected 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";

	@Override
	public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
			Object handler) throws Exception {
		String tracingId;
		//this judgement used for webs context
		if (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 attribute
		request.setAttribute(RESPONSE_TIME, System.currentTimeMillis());
		MDC.put(TRACING_ID, tracingId);
		log.info("tracing.start.url={}", request.getServletPath());
		return super.preHandle(request, response, handler);
	}

	@Override
	public 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 leak
			MDC.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 {
	@Override
	public void addInterceptors(InterceptorRegistry registry) {
		registry.addInterceptor(new ResponseMetricsInterceptor()).addPathPatterns("/**");
	}
}

Effect

向本身的项目发起一次http请求

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

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

能够自行搜索 SOFATracer，比较重，以为通常企业不必应用。