利用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，比較重，以爲通常企業不必應用。