微服務架構去中心化，讓每個業務可以輕鬆獨立出一個高自治性的服務。如今我所參與研發專案，劃分出了幾十個微服務，由不同的團隊負責，這些服務之間相互呼叫。微服務的好處不用多說，但也會因此引發一些問題，例如：
- 測試同事反饋我負責服務的介面報錯了，而往往錯誤的程式不在我的程式碼裡，而是所依賴的下游服務出錯了，然後得去聯絡負責對應服務的團隊。當一個介面報錯了，如何能馬上定位到哪個服務出問題呢？
- 領導提出要提高某個介面的響應速度，可這個介面同樣呼叫了好幾個下游服務介面，該如何定位效能瓶頸呢？
諸如此類的有很多，當微服務越來越多，就越能發現全鏈路日誌的重要性。目前比較常見的解決方案是 Spring Cloud Sleuth，本文講解一下它的使用方法。還會分析一下它實現的原理，然後探討一下基於該原理自定義實現的方案。
1. Sleuth
1.1. 概念
Spring Cloud Sleuth 可以用來追蹤微服務請求中的整個請求，通過它可以記錄各個請求之間的耗時、異常等情況。Sleuth 記錄的這些資訊，需要有系統來收集、儲存和查詢，市場上有很多工具配合，如：Zipkin、Skywalking、pinpoint等。拿最簡單的 Zipkin來說，Spring Cloud Sleuth收集到的一些跟蹤資訊可以傳送給Zipkin，Zipkin提供了圖形化介面方便檢視服務之間的呼叫關係和呼叫耗時等情況。
我們先來看幾個Spring Cloud Sleuth裡面的基本概念。
- service: 服務名，它預設就取spring.application.name。
- span : 直接翻譯就是跨度，比如service1呼叫service2，這一個來回可以算一個span。每個span都由一個唯一的spanId標識。
- trace: 直接翻譯就是追蹤的意思。它由一系列的span組成。通常在第一個服務接收到請求時開啟一個trace，生成一個唯一的traceId，後續的所有追蹤都可以沿用這同一個traceId，這樣就可以來唯一的標識這一整個呼叫鏈路。
- annotation: 標記追蹤過程中的一個事件，記錄事件發生的時間。通過記錄多個事件發生的時間就可以知道任意兩個事件之間的耗時情況。Spring Cloud Sleuth預設會記錄如下這幾種事件。
（1）Client Sent: 客戶端傳送。記錄客戶端發起請求的時間，也是一個span的起點。
（2）Server Received: 服務端接收。記錄服務端接收到請求的時間，它的時間減去客戶端傳送的時間就是客戶端到服務端的網路時延。
（3）Server Sent: 服務端傳送。記錄服務端處理結束，進行結果響應的時間。它的時間減去服務端接收的時間就是服務端業務邏輯處理的時間。
（4）Client Received: 客戶端接收。記錄客戶端完成整個請求，接收到服務端響應內容的時間。它的時間減去客戶端傳送的時間就是客戶端發起請求到接收到服務端響應需要的時間。
（5）Tag: 標籤，可以往span中新增一些Key、Value資訊。
1.2. 日誌
Spring Cloud Sleuth的追蹤資訊中的traceId、spanId會自動的新增到Slf4j的MDC中。所以如果你使用的日誌框架是走的SLF4j規範的，則可以在日誌中使用traceId、spanId變數。
spring 預設日誌框架是 logback，這裡就以 logback-spring.xml 為例，在 pattern 中新增變數 %X{traceId}、%X{spanId} 就能讀到 MDC 中設定的 traceId、spanId 值。
X-B3-* 已被移除
要注意的是，網上一些示例用的是 %X{X-B3-TraceId}、%X{X-B3-SpanId} 來代替上面的值。經親自踩坑，發現在 spring cloud sleuth 3.0.0 版本釋出後，也可對應 spring cloud 2020.0.0 之後，X-B3- 這種寫法已經被移除了。可能在其他地方還能見到，但在 MDC 中已經找不到了。
LOG_LEVEL_PATTERN
還有人要說了，我在引入了 sleuth之後，並沒有建立 logback-spring.xml，也沒有配置 traceId、spanId 這類值。或者建立了 logback-spring.xml，但 pattern 中沒配置 traceId、spanId 的變數，為什麼日誌中也會列印出來呢，就像這樣：
2022-02-20 23:01:28.662 INFO [a-service,d0a7a4be9e9f3ab4,cb4cb09a83e0c553] 20570 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'原因在於，當專案內沒建立 logback-spring.xml 時，預設 pattern 中會包含 LOG_LEVEL_PATTERN 變數，類似於下面這個 logback-spring.xml：
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<property name="CONSOLE_LOG_PATTERN"
value="%d{yyyy-MM-dd HH:mm:ss.SSS} %clr(${LOG_LEVEL_PATTERN:-%5p}) %magenta(${PID:- }) --- [%15.15t] %cyan(%-40.40logger{39}) : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}" />
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="console"/>
</root>
</configuration>而在 sleuth 框架裡面有一個擴充處理類，會將 LOG_LEVEL_PATTERN 變數替換成 %5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}] 值。因此就算沒設定 %X{traceId}等值，依然會顯示。
TraceEnvironmentPostProcessor.java
public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {
Map<String, Object> map = new HashMap();
if (Boolean.parseBoolean(environment.getProperty("spring.sleuth.enabled", "true"))) {
map.put("logging.pattern.level", "%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}]");
}
this.addOrReplace(environment.getPropertySources(), map);
}
2. MDC
MDC(Mapped Diagnostic Contexts) ，翻譯過來就是：對映的診斷上下文 。意思是：在日誌中 （對映的） 請求ID（requestId），可以作為我們定位 （診斷） 問題的關鍵字 （上下文）。
2.1. 基礎
有了MDC工具，只要在介面或切面植入 put 和 remove 程式碼，就可以在定位問題時，根據對映的唯一 requestID 快速過濾出某次請求的所有日誌。另外，當客戶端請求到來時，可以將客戶端id，ip，請求引數等資訊儲存在MDC中，同時在logback.xml中配置，那麼會自動在每個日誌條目中包含這些資訊。
MDC類基本原理其實非常簡單，其內部持有一個ThreadLocal例項，用於儲存context資料，MDC提供了put/get/clear等幾個核心介面，用於操作ThreadLocal中的資料；ThreadLocal中的K-V，可以在logback.xml中宣告，即在layout中通過宣告 %X{Key} 來列印MDC中儲存的此key對應的value在日誌中。
例如下面定義過濾器
public class TraceFilter implements Filter {
@Override
public void init(FilterConfig filterConfig) throws ServletException {
log.info("<<< 初始化TraceFilter>>>");
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
try {
final HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest;
String requestURI = httpServletRequest.getRequestURI();
MDC.put("requestURI", requestURI);
// 放行
filterChain.doFilter(servletRequest, servletResponse);
} finally {
// 請求MDC 的內容
MDC.clear();
}
}
@Override
public void destroy() {
log.info("<<< 銷燬TraceFilter>>>");
MDC.clear();
}
}配置logback-spring.xml
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout>
<Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) [%X{requestURI}] %thread %logger Line:%-3L - %msg%n </Pattern>
</layout>
</appender> 在使用MDC時需要注意一些問題，這些問題通常也是ThreadLocal引起的，比如我們需要線上程退出之前清除（clear）MDC中的資料；線上程池中使用MDC時，那麼需要在子執行緒退出之前清除資料；可以呼叫MDC.clear()方法。
slf4j的MDC機制其內部基於ThreadLocal實現，所以我們呼叫 MDC.put()方法傳入的請求ID只在當前執行緒有效。所以，主執行緒中設定的MDC資料，在其子執行緒（執行緒池）中是無法獲取的。那麼主執行緒如何將MDC資料傳遞給子執行緒？官方建議:
- 在父執行緒新建子執行緒之前呼叫
MDC.getCopyOfContextMap()方法將MDC內容取出來傳給子執行緒。 - 子執行緒在執行操作前先呼叫
MDC.setContextMap()方法將父執行緒的MDC內容設定到子執行緒。
例如下面的執行緒池：
public class ExecutorMDCTest {
private static final AtomicInteger num = new AtomicInteger(1);
static ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(
5,
5 + 1,
60L,
TimeUnit.SECONDS,
new LinkedBlockingDeque<>(10_00), new ThreadFactory() {
@Override
public Thread newThread(Runnable r) {
return new Thread(r, "test-thread" + num.getAndIncrement());
}
});
static public void main(String[] args) throws Exception {
Logger log = LoggerFactory.getLogger(ExecutorMDCTest.class);
MDC.put("bl-traceid", "988f54f4bdd34920a53d908827a9fa59");
Map<String, String> copyOfContextMap = MDC.getCopyOfContextMap();
// 執行緒池
threadPoolExecutor.execute(() -> {
// 會丟失日誌
log.info("測試列印日誌4：{}", "data");
MDC.setContextMap(copyOfContextMap);
log.info("設定後-測試列印日誌5：{}", "data");
});
}
}配置logback-spring.xml
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout>
<Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) [%X{bl-traceid}] %thread %logger Line:%-3L - %msg%n </Pattern>
</layout>
</appender>2.2. Slf4j中的MDC
Slf4j MDC 內部實現很簡單。實現一個單例對應例項，獲取具體的MDC實現類，然後其對外介面，就是對引數進行校驗，然後呼叫 MDCAdapter 的方法實現。MDCAdapter 是個介面類，當日志框架使用 Logback 時，對應介面的實現類就是 LogbackMDCAdapter，所以核心的實現類還是它，下面就列出程式碼：
public class LogbackMDCAdapter implements MDCAdapter {
final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal();
private static final int WRITE_OPERATION = 1;
private static final int MAP_COPY_OPERATION = 2;
final ThreadLocal<Integer> lastOperation = new ThreadLocal();
public LogbackMDCAdapter() {
}
private Integer getAndSetLastOperation(int op) {
Integer lastOp = (Integer)this.lastOperation.get();
this.lastOperation.set(op);
return lastOp;
}
private boolean wasLastOpReadOrNull(Integer lastOp) {
return lastOp == null || lastOp == 2;
}
private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) {
Map<String, String> newMap = Collections.synchronizedMap(new HashMap());
if (oldMap != null) {
synchronized(oldMap) {
newMap.putAll(oldMap);
}
}
this.copyOnThreadLocal.set(newMap);
return newMap;
}
public void put(String key, String val) throws IllegalArgumentException {
if (key == null) {
throw new IllegalArgumentException("key cannot be null");
} else {
Map<String, String> oldMap = (Map)this.copyOnThreadLocal.get();
Integer lastOp = this.getAndSetLastOperation(1);
if (!this.wasLastOpReadOrNull(lastOp) && oldMap != null) {
oldMap.put(key, val);
} else {
Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
}
}
}
public void remove(String key) {
if (key != null) {
Map<String, String> oldMap = (Map)this.copyOnThreadLocal.get();
if (oldMap != null) {
Integer lastOp = this.getAndSetLastOperation(1);
if (this.wasLastOpReadOrNull(lastOp)) {
Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
newMap.remove(key);
} else {
oldMap.remove(key);
}
}
}
}
public void clear() {
this.lastOperation.set(1);
this.copyOnThreadLocal.remove();
}
public String get(String key) {
Map<String, String> map = (Map)this.copyOnThreadLocal.get();
return map != null && key != null ? (String)map.get(key) : null;
}
public Map<String, String> getPropertyMap() {
this.lastOperation.set(2);
return (Map)this.copyOnThreadLocal.get();
}
public Set<String> getKeys() {
Map<String, String> map = this.getPropertyMap();
return map != null ? map.keySet() : null;
}
public Map<String, String> getCopyOfContextMap() {
Map<String, String> hashMap = (Map)this.copyOnThreadLocal.get();
return hashMap == null ? null : new HashMap(hashMap);
}
public void setContextMap(Map<String, String> contextMap) {
this.lastOperation.set(1);
Map<String, String> newMap = Collections.synchronizedMap(new HashMap());
newMap.putAll(contextMap);
this.copyOnThreadLocal.set(newMap);
}
}
值得注意的是，早期 LogbackMDCAdapter 類中定義 copyOnThreadLocal 的是 InheritableThreadLocal ，網上看到的很多資料都是說這種。InheritableThreadLocal 相較於 TreadLocal 的特點在於：InheritableThreadLocal<T> 是對ThreadLocal<T> 的擴充套件和繼承，它的資料ThreadLocal.ThreadLocalMap儲存在Thread的inheritableThreadLocals變數中，同時如果我們在當前執行緒開啟一個新執行緒，而且當前執行緒存在inheritableThreadLocals變數，那麼子執行緒會copy一份當前執行緒（父執行緒）中的這個變數持有的值。
但是在 LogbackMDCAdapter 中直接使用 InheritableThreadLocal 定義變數，預設都對子執行緒複製，影響效能，在如今最新版本已經改成 ThreadLocal 了。
3. sleuth原理
3.1. http跟蹤
為了實現請求鏈路跟蹤，當請求傳送到分散式系統的入口時，只需要在服務跟蹤框架為該請求建立唯一的跟蹤標識，並保證該標識在在分散式系統內部流轉，直到返回請求為止。該標識即為 traceId，通過該標識，就能將不同服務呼叫的日誌串聯起來。
為了統計各處理單元(應用服務)的延遲，當請求到達或處理邏輯達到某個狀態時，也通過一個唯一標識來標記開始、具體過程及結束(標識一個服務內請求進入、處理到結束)，該標識即為 spanId。對於每個 spanId 來說，必須有開始和結束兩個節點，通過計算開始 span 和 結束 span 的時間戳，就能統記出該 span 的時間延遲。
而在 Http 請求鏈中，保障 traceId 在每個服務中傳遞的方式，是在基於 Http 的服務呼叫時，將 traceId 等資訊通過 Http請求頭傳遞過去。可以試驗一下，在正常 feign 呼叫的下游方法中列印出所有請求頭：
@GetMapping("/hello")
public String hello(@RequestParam String name, @RequestHeader Map<String, String> headers) {
log.info("headers:{}", headers);
}日誌內容如下，包含了引數： x-b3-traceid、x-b3-spanid、x-b3-parentspanid、x-b3-sampled=1。
headers:{x-b3-traceid=6dd57dc2ad55c58f, x-b3-spanid=b5e6de658b261ac7, x-b3-parentspanid=6dd57dc2ad55c58f, x-b3-sampled=1, accept=*/*, user-agent=Java/1.8.0_202, host=localhost:8081, connection=keep-alive}在下游的服務接受呼叫時，sleuth 框架的 LazyTracingFilter 會做處理，從Http Request的Header裡獲取Span資料，如果Header中存在 x-b3-traceid、x-b3-spanid 等屬性，就說明呼叫鏈前一個節點已經生成 span，並傳遞下來，這時可以直接使用這些span資料。否則，建立一個新的span。
3.2. 多執行緒跟蹤
前面說 MDC 是基於 ThreadLocal 實現的，意味著當前執行緒儲存的 traceId、spanId 等資料，在子執行緒將無法傳遞。但這樣明顯不符合我們期望的，根據一個 traceId 跟蹤完整鏈路的想法。
還是基於前面的例子，在下游方法中列印：
@Resource
private Executor asyncExecutor;
@GetMapping("/hello")
public String hello(@RequestParam String name, @RequestHeader Map<String, String> headers) {
log.info("headers:{}", headers);
CompletableFuture.runAsync(() -> this.syncPrint(), asyncExecutor);
log.info("exec:{}", asyncExecutor.toString());
}
void syncPrint() {
log.info("非同步列印");
}
// ... 配置類中定義 bean
@Bean("asyncExecutor")
public Executor getAsyncExecutor() {
ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(7);
threadPoolTaskExecutor.setMaxPoolSize(42);
threadPoolTaskExecutor.setQueueCapacity(11);
threadPoolTaskExecutor.setThreadNamePrefix("MyExecutor-");
threadPoolTaskExecutor.initialize();
return threadPoolTaskExecutor;
}列印的結果是：
2022-02-28 23:14:40.711 INFO [a-service,14b328adfec294a8,739f0082a7cbaa19] 23400 --- [nio-8081-exec-1] p.k.aservice.controller.HelloController : headers:{x-b3-traceid=14b328adfec294a8, x-b3-spanid=739f0082a7cbaa19, x-b3-parentspanid=14b328adfec294a8, x-b3-sampled=1, accept=*/*, user-agent=Java/1.8.0_202, host=localhost:8081, connection=keep-alive}
2022-02-28 23:14:40.718 INFO [a-service,14b328adfec294a8,739f0082a7cbaa19] 23400 --- [nio-8081-exec-1] p.k.aservice.controller.HelloController : exec:org.springframework.cloud.sleuth.instrument.async.LazyTraceThreadPoolTaskExecutor@72864083
2022-02-28 23:14:40.720 INFO [a-service,14b328adfec294a8,060fcae6ba359b01] 23400 --- [ MyExecutor-1] p.k.aservice.controller.HelloController : 非同步列印其實我還做了幾個實驗，最終列印的結果相同：
- 如果程式碼中沒有註冊
asyncExecutor的 bean，直接使用 Spring 預設的執行緒池，列印出來的結果還是一樣。 - 如果程式碼中沒有使用
CompletableFuture.runAsync來執行非同步方法，而是將方法寫在另外的類，通過 @Async 呼叫，列印出來的結果還是一樣。
要想找到原因，就從 asyncExecutor.toString() 列印出來的結果入手：org.springframework.cloud.sleuth.instrument.async.LazyTraceThreadPoolTaskExecutor@72864083。通過搜尋原始碼，發現 sleuth 框架定義了自動配置，會將 spring 容器中註冊的執行緒池 bean 代理成 LazyTraceThreadPoolTaskExecutor，而 LazyTraceThreadPoolTaskExecutor 這個框架自定義的執行緒池 能實現對 traceId 等資訊的傳遞。
開啟代理通過配置引數 spring.sleuth.async.enabled，因為預設值即 true，因此預設開啟。如果部分自定義執行緒的 bean 不想如此代理，還可以配置 spring.sleuth.async.ignored-beans。
不過如果將上述程式碼中非同步列印部分改成 CompletableFuture.runAsync(() -> this.syncPrint());，列印的結果是：
2022-02-28 23:14:40.715 INFO [a-service,,] 23400 --- [onPool-worker-1] p.k.aservice.controller.HelloController : 非同步列印原因在於此時並沒有使用 spring 容器中的執行緒池 bean，而是預設使用 jdk 中的 ForkJoinPool.commonPool()，因為並未被代理。
3.3. 配合 zipkin 使用
通俗來說，zipkin server 採集 sleuth 在客戶端的資料，並提供視覺化介面做查詢展示。
這裡用 docker 簡單啟一個 zipkin server：
docker run -d \
--name zipkin \
--restart=on-failure:3 \
-p 9411:9411 \
openzipkin/zipkinpom.xml中引入zipkin客戶端依賴：
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-sleuth-zipkin</artifactId>
</dependency>application.properties 中配置 zipkin server 地址：
spring.zipkin.base-url=http://localhost:9411這樣就好了，正常執行包含 sleuth 的專案後，在瀏覽器中訪問地址：http://localhost:9411 ，就進入了 zipkin 介面。並且可以查詢鏈路日誌。
當然 zipkin 的實際配置沒這麼簡單，它要做 sleuth 的資料取樣，往往還要和 MQ 配合使用。但這些不是本文重點，況且如今也很少有公司選擇 zipkin。
4. 補充方案設想
sleuth 實現全鏈路日誌的方案比較清晰，回頭看前面的問題：
- 如今排查問題，首先就是找到該次請求的 traceId，然後就可以從 elk 中撈任何我想要的日誌了。當查到呼叫其他服務報錯的日誌時，直接拿著 traceId 聯絡負責下游服務的團隊即可。
- 效能優化時，可以通過圖形化介面看到每個 span 的處理時間。從而一目瞭然地定位到效能瓶頸處。
但實際專案中，針對有些應用場景，原生的 sleuth 也是鞭長莫及。但我們可以模仿它的實現方案做一些補充方案：
MQ 的鏈路日誌
有些業務場景中，我希望能將 MQ 的生產者和消費者連起來，通過生產者的 traceId，也能看到訊息被消費的鏈路日誌。
這裡應該可以類似 http 的做法，生產者傳送訊息時將 traceId 等資料放入訊息頭中，當消費者接收訊息時從訊息頭中獲取，作為 traceId 繼續傳遞。
異常 Response屬性
很多人都會在專案中基於 ExceptionHandler 做同一異常處理，返回體中一般都會包含狀態碼、常見錯誤內容等關鍵資訊。但既然是異常處理，最重要的就是排查錯誤，應該必須包含 traceId。
自定義鏈路追蹤
基於 sleuth、zipkin 的實現方案，我們是不是可以自己開發一套定製的全鏈路日誌方案呢？
- 可以不用像 sleuth 有很細的粒度，例如基於執行緒的 span 等。我們只記錄單個微服務請求、mq消費等粗粒度的引數。
- 還是基於請求頭來傳遞 traceId，在服務請求、響應處做攔截器，服務呼叫時做 aop，以及異常日誌的捕獲等，然後將日誌資訊上傳給負責鏈路日誌收集的服務來處理。
- 單獨開發一個記錄鏈路日誌的微服務，一方面蒐集所有微服務埋點處上傳的日誌，另一方面做自定義的資料分析。例如：可以像 zipkin一樣通過 traceId 查詢全鏈路日誌；還可以做效能分析看板，找出請求時間長的鏈路、報錯的鏈路、呼叫最頻繁的服務等等。當問題到達閾值，甚至可以給運維人員做訊息推送。