一、技術原理
1.1 背景
微服務架構是一個分布式架構,它按業務划分服務單元,一個分布式系統往往有很多個服務單元。由於服務單元數量眾多,業務的復雜性,如果出現了錯誤和異常,很難去定位。主要體現在,一個請求可能需要調用很多個服務,而內部服務的調用復雜性,決定了問題難以定位。所以微服務架構中,必須實現分布式鏈路追蹤,去跟進一個請求到底有哪些服務參與,參與的順序又是怎樣的,從而達到每個請求的步驟清晰可見,出了問題,很快定位。
舉個例子,在微服務系統中,一個來自用戶的請求,請求先達到前端A(如前端界面),然后通過遠程調用,達到系統的中間件B、C(如負載均衡、網關等),最后達到后端服務D、E,后端經過一系列的業務邏輯計算最后將數據返回給用戶。對於這樣一個請求,經歷了這么多個服務,怎么樣將它的請求過程的數據記錄下來呢?這就需要用到服務鏈路追蹤。
Google開源的 Dapper鏈路追蹤組件,並在2010年發表了論文《Dapper, a Large-Scale Distributed Systems Tracing Infrastructure》,這篇文章是業內實現鏈路追蹤的標桿和理論基礎,具有非常大的參考價值。
目前,鏈路追蹤組件有Google的Dapper,Twitter 的Zipkin,以及阿里的Eagleeye (鷹眼)等,它們都是非常優秀的鏈路追蹤開源組件。
1.2 名詞術語
微服務鏈路追蹤系統實現時,需設置一些關鍵節點記錄信息,鏈路追蹤相關名詞如下:
Span:基本工作單元,發送一個遠程調度任務 就會產生一個Span,Span是一個64位ID唯一標識的,Trace是用另一個64位ID唯一標識的,Span還有其他數據信息,比如摘要、時間戳事件、Span的ID、以及進度ID。
Trace:一系列Span組成的一個樹狀結構。請求一個微服務系統的API接口,這個API接口,需要調用多個微服務,調用每個微服務都會產生一個新的Span,所有由這個請求產生的Span組成了這個Trace。
Annotation:用來及時記錄一個事件的,一些核心注解用來定義一個請求的開始和結束 。這些注解包括以下:
cs - Client Sent -客戶端發送一個請求,這個注解描述了這個Span的開始
sr - Server Received -服務端獲得請求並准備開始處理它,如果將其sr減去cs時間戳便可得到網絡傳輸的時間。
ss - Server Sent (服務端發送響應)–該注解表明請求處理的完成(當請求返回客戶端),如果ss的時間戳減去sr時間戳,就可以得到服務器請求的時間。
cr - Client Received (客戶端接收響應)-此時Span的結束,如果cr的時間戳減去cs時間戳便可以得到整個請求所消耗的時間。
1.3 調用鏈分析
一個服務調用過程如下圖所示:

二、技術實現
調用方每一次向系統服務發起請求時,會生成這一次調用產生的相關調用鏈日志,生成一個全局的traceId,生成不同節點的span信息。其中當首個服務生成全局編碼后,放入到header中,基於http傳遞給下級服務(其他模式類似)。下級服務可通過設置Filter過濾器(其他方案也可以),接收鏈路日志編碼,並記錄調用的日志信息。在將全局編碼繼續傳遞給下級服務。最終本次業務調用完成后,記錄調用日志並清空本次調用鏈產生的全局編碼。簡易流程如下圖所示:

2.1 單服務流程說明
- 調用方請求服務A,進入服務A過濾器;
- 服務A過濾器判斷請求的header中是否攜帶了TraceId,ParentSpanId,有則使用攜帶的,沒有就自動生成。
- 過濾器前置部分記錄初始請求的一些信息,如請求地址,參數,請求時間等;
- 過濾器轉發請求進入到Service方法;
- 過濾器后置部分再次記錄Service方法執行完成后的一些信息,如返回內容,結束時間;
- 過濾器前后分別記錄了信息,組合生成調用鏈路日志;
- 請求完成后,清空本次產生的TraceId;
服務A調用鏈日志信息參考:

// trace日志 { "message":"trace log", "context":{ "trace_id":"e0d5c5ba-f497-4407-b8ca-f657a88452fc517513", "request_uri":"/customize-trace-A/trace/jdk/async", "request_method":"GET", "refer_service_name":null, "service_name":"customize-trace-A", "refer_service_host":"127.0.0.1", "request_time":1608896030.689531, "response_time":1608896030.692276, "time_used":3.479, "service_addr":"192.168.45.42", "service_port":8095, "request_id":"9adfcf3c-d606-418f-abc7-6600bff6adf0533098" }, "datetime":"2020-12-25 19:33:50.690014" } // span節點 { "trace_id":"e0d5c5ba-f497-4407-b8ca-f657a88452fc517513", "request_id":"9adfcf3c-d606-418f-abc7-6600bff6adf0533098", "span":{ "span_id":"eb12eaf8-df3d-4dd2-923a-685360a4fd79588942", "parent_id":null, "duration":3426, "annotations":[ { "timestamp":1608896030686322, "action":"sr" }, { "timestamp":1608896030689748, "action":"ss" } ] } , "datetime":"2020-12-25 19:34:50.690014" }
2.2 多服務流程說明
多個服務與單個服務對比,是在不同的微服務里面分別記錄對應的Trace信息,Span信息。同一個調用請求,所有微服務記錄的TraceId一致,父服務的SpanId為子服務的ParentSpanId。
舉例兩個服務間的調用流程如下:
- 調用方發起調用,請求服務A,進入服務A過濾器;
- 服務A過濾器判斷請求的header中是否攜帶了TraceId,ParentSpanId,有則使用攜帶的,沒有就自動生成;
- 服務A過濾器前置部分記錄初始請求的一些信息,如請求地址,參數,請求時間等;
- 服務A過濾器轉發請求進入到Service方法;
- 服務A的Service方法內部執行部分邏輯后,開始通過中間件調用服務B;
- 將服務A中已生成的TraceId,ParentSpanId信息,通過header設置參數(其他類似)的模式傳遞給服務B;
- 進入服務B過濾器,服務B過濾器獲取header中傳遞過來的TraceId,ParentSpanId;
- 服務B過濾器前置部分記錄初始請求的一些信息,如請求地址,參數,請求時間等
- 服務B過濾器轉發請求進入到Service方法;
- 服務B過濾器后置部分再次記錄Service方法執行完成后的一些信息,如返回內容,結束時間;
- 服務B過濾器前后分別記錄了信息,組合生成調用鏈路日志;
- 服務B基於中間件返回調用的請求信息處理結果給服務A;
- 服務A清空本次接收到的TraceId等編碼信息。
- 服務A過濾器后置部分再次記錄Service方法執行完成后的一些信息,如返回內容,結束時間;
- 服務A過濾器前后分別記錄了信息,組合生成調用鏈路日志;
- 服務A清空本次請求產生的TraceId。
2.3 中間件記錄Span信息
中間件是否需要記錄Span信息
上述舉例並未記錄服務的Service方法執行一段時間后,何時通過中間件發起調用其他服務的Span信息。現實業務中,服務調用經常存在這種情況,服務A中某一個方法,先調用了服務B,獲取到服務B的返回結果后,后續還又調用了服務C,服務D。此刻若不記錄中間件的Span信息,在分析部分調用鏈超時情況時,會難以定位分析。只能獲取到接受方的接收時間,不知道某一個服務調用時具體的發起時間(如服務D最終接收請求時的時間與最初進入服務A記錄的請求時間相差一分鍾,但這並不能說服務A調用服務D的接口就耗時一分鍾)。
因此,中間件模塊記錄Span信息也至關重要。比如一個http請求的中間件,可重寫他的Client實現類,記錄開始發起請求和請求完成(類似於Filter)這一段時間的Span信息。
2.4 TraceId的管理
- 為什么每次服務調用完成后,需要清空traceId?
- 多個請求同時發起時,如何保證調用鏈日志在不同線程中隔離,互不影響?
每一個請求過來時,產生一個獨立的子線程,在這個子線程內部設置對應的traceId,可基於ThreadLocal存儲調用鏈相關信息,達到子線程信息隔離的目的。
了解調用鏈信息基本原理后,自定義編碼實現一套基於traceId的調用鏈追蹤技術方案,需解決如下問題:
- 全局traceId的生成和清空;
- traceId調用鏈路傳遞與追蹤;
- traceId基於Filter接收;
- Span生成與管理;
- 調用鏈路日志存儲;
三、技術細節分析
3.1 生成調用鏈相關編碼
traceId:全局調用鏈日志id編碼,在多個服務調用的一條調用鏈日志中,為同一個日志編碼
spanId:spanId節點的唯一編碼
requestId:本次請求生成的唯一id編碼,在多個服務調用的一條調用鏈日志中,為不同的日志編碼
每一次發起業務調用完成后,需清空本次產生的編碼。同時,不同線程的調用鏈日志應互不影響。故調用鏈信息可基於MDC技術實現,查看MDC的實現原理,本質還是基於ThreadLocal實現。本例直接基於ThreadLocal實現,部分偽代碼如下:

public class LoggerUtil{ /** * 生成traceId ,requestId,spanId 類似,設置不同的方法名即可 */ static String traceId() { return UUID.randomUUID().toString() + new Random().nextInt(1000000); } } public final class ThreadHolderUtil { /** * 任意類型數據集合 */ private static final ThreadLocal<Map<Object, Object>> VALUE_MAP = ThreadLocal.withInitial(HashMap::new); /** * 設置key值 * * @param key key * @param value 值 */ public static void setValue(Object key, Object value) { Optional.ofNullable(VALUE_MAP.get()).ifPresent(valueMap -> valueMap.put(key, value)); } /** * 清除指定Key * * @param key 指定key */ public static void clearValue(Object key) { Optional.ofNullable(VALUE_MAP.get()).ifPresent(valueMap -> valueMap.remove(key)); } /** * 清除整個map */ public static void clearValueMap() { VALUE_MAP.remove(); } }
- 獲取traceId:String traceId = LoggerUtil.traceId();
- 單次調用過程中存儲traceId:ThreadHolderUtil.setValue(TRACD_ID, traceId );
- 整個調用完成后,清空整個變量:ThreadHolderUtil.clearValueMap();
3.2 調用鏈編碼傳遞
調用鏈編碼傳遞主要是一個請求涉及到多個微服務時,一般是從網關(或首個請求的微服務)生成調用鏈編碼后,該編碼在不同微服務中的流轉過程。本文主要介紹Feign和線程池中traceId的鏈路傳遞
參考文檔:
基於TraceId鏈路追蹤
Feign傳遞編碼-重寫RequestInterceptor
網上介紹方案大多是通過重寫實現RequestInterceptor接口實現的。參考代碼如下:

/** * 調用服務追蹤信息feign攔截器 * */ public class FeignTraceInterceptor implements RequestInterceptor { private static final Logger LOGGER = LoggerUtil.getTraceLogger(); @Override public void apply(RequestTemplate template) { String projectName = LoggerUtil.PROJECT_NAME; if (!StringUtils.isEmpty(projectName)) { template.header(REFER_SERVICE_NAME, projectName); } if (!StringUtils.isEmpty(HOST_IP)) { template.header(REFER_REQUEST_HOST, HOST_IP); } String traceId = TraceUtil.getTraceId(); if (StringUtils.isEmpty(traceId)) { traceId = LoggerUtil.traceId(); } template.header(GATEWAY_TRACE, traceId); String spanId = TraceContext.parentSpanId(); template.header(PARENT_ID_HEADER, spanId); } } @ConditionalOnClass(Feign.class) public static class FeignTraceAutoConfiguration { @Bean public FeignTraceInterceptor feignTraceInterceptor() { return new FeignTraceInterceptor(); } }
該方案是把調用鏈編碼通過header傳遞給下級服務了,但並沒有記錄Feign處的Span信息。參考模型如下圖所示:

Feign傳遞編碼-重新實現內部調用的 Http Client
擴展方案是需要記錄每一次調用Feign時,記錄Feign處的Span信息。Feign最終可通過在http發起請求時,調整內部的Http Client擴展實現,達到記錄Span信息的目的。(整體方案偏復雜,要考慮負載均衡時,池化請求等模式時,都可以記錄信息)
Feign添加自定義注解
目的是為了記錄Feign在執行方法前后的調用鏈信息,可采用加入注解,在Feign類上面標記,記錄方法執行前后時的情況。調用鏈信息還是通過重寫RequestInterceptor實現傳遞給下級服務。
采用Feign調用其他服務,記錄Fegin的Span信息,可通過方案:
(Feign傳遞編碼重寫RequestInterceptor, Feign請求添加注解,組合實現。)
編寫一個注解,並記錄調用方法前后的時間信息,參考偽代碼:

@Aspect @Component public class FeignSpanAspect { @Pointcut("@annotation(com.trace.base.tool.annotation.FeignSpan)") public void pointcut() { } @Around("pointcut()") public void around(ProceedingJoinPoint joinPoint) { try { // 先生成spanId String spanId = TraceContext.parentSpanId(); ThreadHolderUtil.setValue("feign-spanId", spanId); // cs Annotation cs = TraceContext.cs(); List<Annotation> annotations = new ArrayList<>(2); annotations.add(cs); // 避免執行超時,所以先設置span cs信息 Span span = new Span.Builder() .parentId(ThreadHolderUtil.getValue(PARENT_SPAN_ID_KEY, String.class)) .spanId(spanId) .annotations(annotations) .build(); List<Span> subSpanList = ThreadHolderUtil.getValue(SUB_SPAN_LIST_KEY, List.class); if (subSpanList != null) { subSpanList.add(span); } joinPoint.proceed(); // cr Annotation cr = TraceContext.cr(); // 增加cr annotations.add(cr); span.setDuration(cr.getTimestamp() - cs.getTimestamp()); } catch (Throwable throwable) { throwable.printStackTrace(); } } }
線程池傳遞編碼
主線程中記錄的調用鏈信息通過線程池執行時,子線程會獲取不到主線程的調用鏈信息(子線程獲取traceId為null)。因此,需要在子線程執行時,主線程向子線程傳遞調用鏈相關編碼信息。參考文檔:
多線程相關知識:
多線程-JUC線程池
Spring 回調方法裝飾器:
多線程調用如何傳遞上下文
JDK原生擴展Callable,Runnable:
traceId跟蹤請求全流程日志
3.3 微服務過濾器接收調用鏈編碼
上游服務向下游服務發起調用請求時,下游服務接收到請求時,加入一個基礎過濾器(設置過濾器order值小於其他業務的order值,保證優先執行),獲取上游服務請求信息中的調用鏈信息,獲取出來后,記錄請求Trace日志信息,並通過ThreadLocal模式,記錄調用鏈信息。參考實現部分偽代碼如下:

@Override public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { HttpServletRequest servletRequest = (HttpServletRequest) request; String uri = servletRequest.getRequestURI(); // 服務健康檢查日志不統計,根目錄和HEAD請求忽略 final String slash = "/"; if (Arrays.stream(ignorePath).anyMatch(uri::startsWith) || slash.equals(uri) || HttpMethod.HEAD.name().equalsIgnoreCase(servletRequest.getMethod())) { chain.doFilter(request, response); } else { try { int port = request.getLocalPort(); TraceLog traceLog = new TraceLog(); traceLog.setRequestTime(getNowUs()); //服務名稱 traceLog.setServiceName(LoggerUtil.PROJECT_NAME); // 開始時間戳(微秒) long start = LocalDateTimeUtil.getCurrentMicroSecond(); // traceId String traceId = servletRequest.getHeader(GATEWAY_TRACE); // 沒有就新生成一個 if (StringUtils.isEmpty(traceId)) { traceId = LoggerUtil.traceId(); } // 嘗試獲取上游傳遞的parent_id String parentId = servletRequest.getHeader(TraceContext.PARENT_ID_HEADER); // 首先設置span id,作為后續子span的父span id String spanId = TraceContext.parentSpanId(); ThreadHolderUtil.setValue(PARENT_SPAN_ID_KEY, spanId); // 需要提前初始化子span列表,否則父子線程無法持有一個數據引用 ThreadHolderUtil.setValue(SUB_SPAN_LIST_KEY, new ArrayList<>()); // sr Annotation sr = TraceContext.sr(); String requestId = LoggerUtil.requestId(); // 設置trace,用於ResponseBody能夠獲取 Trace trace = new Trace(traceId, requestId); ThreadHolderUtil.setValue(TRACE_KEY, trace); traceLog.setTraceId(traceId); // 遠程調用服務名稱 traceLog.setReferServiceName(servletRequest.getHeader(REFER_SERVICE_NAME)); traceLog.setRequestUri(servletRequest.getRequestURI()); String method = servletRequest.getMethod(); traceLog.setRequestMethod(method); traceLog.setServicePort(port); // 原始response對象 chain.doFilter(request, response); // 結束時間戳(微秒) long end = LocalDateTimeUtil.getCurrentMicroSecond(); // ss Annotation ss = TraceContext.ss(); // duration long duration = ss.getTimestamp() - sr.getTimestamp(); // span日志 SpanLog spanLog = new SpanLog(); // 父span Span span = new Span.Builder() .parentId(parentId) .spanId(spanId) .duration(duration) .annotations(Arrays.asList(sr, ss)) .build(); spanLog.setTraceId(traceId); spanLog.setRequestId(requestId); spanLog.setSpan(span); List<Span> subSpanList = ThreadHolderUtil.getValue(SUB_SPAN_LIST_KEY, List.class); spanLog.setSubSpans(subSpanList); // todo 存儲span信息 // todo 存儲trace信息 } finally { // 最后清除VALUE_MAP // 執行完成后,清空產生的日志信息 ThreadHolderUtil.clearValueMap(); } } }
3.4 Span生成與管理
通過技術原理分析,生成Span的場景為每一個微服務請求開始至請求完成時,記錄一個Span節點信息。若服務執行過程中,通過中間件調用了其他微服務時,每一次中間件調用時,再記錄一個Span節點信息(調用多少次,記錄多少個)。
3.5 調用鏈日志存儲
發起一次調用后,會生成Trace請求信息,Span節點信息,針對這些日志信息,可以通過寫入到Log4g2日志中。或者寫入到其他數據庫等系統中做日志信息存儲,便於后續分析問題。
舉例一個場景:
發起請求,先調用服務A,服務A通過Feign調用一次服務B,整體記錄日志參考如下:
服務A對應traceLog
- 生成全局traceId: 2bf002c7-c140-4304-9c42-98ec0e359e1a314225。
- 服務A調用起止時間:1612344583.027557~ 1612344589.716305。

{ "message":"trace log", "context":{ "trace_id":"2bf002c7-c140-4304-9c42-98ec0e359e1a314225", "request_uri":"/customize-trace-A/trace/feign/name", "request_method":"GET", "refer_service_name":null, "service_name":"customize-trace-A", "refer_service_host":"127.0.0.1", "request_time":1612344583.027557, "response_time":1612344589.716305, "time_used":4774.917, "service_addr":"192.168.45.42", "service_port":8095, "request_id":"01d91c6f-1745-414c-a556-06d2e2630995119672" }, "level":200, "level_name":"INFO", "channel":"REQUEST", "datetime":"2021-02-03 17:29:50.405499" }
服務A對應spanLog
- 服務A本身具備一個span節點信息。且服務A的spanId,為sub_spans的parentSpanId。因為服務A通過Feign調用了一次服務B,記錄中間件的Span信息一次。(調用多少次,記錄多少個孩子span節點。)
- 孩子節點的span信息,內部的開始請求時間,結束請求時間,小於上級節點的起止時間。
全局traceId:
2bf002c7-c140-4304-9c42-98ec0e359e1a314225。
- sub_spans 節點下面,所有相關的子節點,他的parentId為上級span節點的spanId,值為e495b1e3-72e3-4dfc-92ad-8526c1c05e68901528。

{ "message":"span log", "context":{ "trace_id":"2bf002c7-c140-4304-9c42-98ec0e359e1a314225", "request_id":"01d91c6f-1745-414c-a556-06d2e2630995119672", "span":{ "span_id":"e495b1e3-72e3-4dfc-92ad-8526c1c05e68901528", "parent_id":null, "duration":4772900, "annotations":[ { "timestamp":1612344583030172, "action":"sr" }, { "timestamp":1612344587803072, "action":"ss" } ] }, "request_uri":null, "request_method":null, "sub_spans":[ { "span_id":"6a112df7-762d-4467-aab5-8d4ea8d30e34265554", "parent_id":"e495b1e3-72e3-4dfc-92ad-8526c1c05e68901528", "duration":4064421, "annotations":[ { "timestamp":1612344583090733, "action":"cs" }, { "timestamp":1612344587155154, "action":"cr" } ] } ] }, "level":200, "level_name":"INFO", "channel":"SPAN", "datetime":"2021-02-03 17:29:49.705213" }
服務B對應traceLog
- 服務B接收上級的傳入的TraceId,全局編碼:2bf002c7-c140-4304-9c42-98ec0e359e1a314225。
- 服務B調用起止時間:1612344586.914167~ 1612344587.162829.
- 服務A通過Feign發起的時間為: 1612344583090733,服務B接收到的請求時間1612344586914167,表明中間件到服務B中還是存在細微的時間差。

{ "message":"trace log", "context":{ "trace_id":"2bf002c7-c140-4304-9c42-98ec0e359e1a314225", "request_uri":"/customize-trace-B/trace/name", "request_method":"GET", "refer_service_name":"customize-trace-A", "service_name":"customize-trace-B", "refer_service_host":"127.0.0.1", "request_time":1612344586.914167, "response_time":1612344587.162829, "time_used":218.196, "service_addr":"192.168.45.42", "service_port":8096, "request_id":"c3141791-b5c4-49e3-ad4a-08c40782f687651638" }, "level":200, "level_name":"INFO", "channel":"REQUEST", "datetime":"2021-02-03 17:29:47.161630" }
服務B對應spanLog
- 服務B接收上級的傳入的TraceId,全局編碼:2bf002c7-c140-4304-9c42-98ec0e359e1a314225.
- 服務B沒有再次調用其他的服務了,故不存在下級sub_spans節點。
- 服務B節點信息中的parent_id,為服務A中的孩子節點spanId,值為:6a112df7-762d-4467-aab5-8d4ea8d30e34265554。

{ "message":"span log", "context":{ "trace_id":"2bf002c7-c140-4304-9c42-98ec0e359e1a314225", "request_id":"c3141791-b5c4-49e3-ad4a-08c40782f687651638", "span":{ "span_id":"d4a7f2d5-d49d-4f88-95ee-4f73c18ff9d5967084", "parent_id":"6a112df7-762d-4467-aab5-8d4ea8d30e34265554", "duration":207818, "annotations":[ { "timestamp":1612344586929937, "action":"sr" }, { "timestamp":1612344587137755, "action":"ss" } ] }, "request_uri":null, "request_method":null, "sub_spans":[ ] }, "level":200, "level_name":"INFO", "channel":"SPAN", "datetime":"2021-02-03 17:29:47.139560" }
四、自實現方案優缺點
- 自定義一個調用鏈插件,便於根據項目需求,充分的定制化開發。
- 結合公司項目的需求,調整調用鏈方案,在調用鏈模塊成熟后,可做為中間件模塊,應用於公司的其他項目;
- 實現一個調用鏈插件,有利於了解整個調用鏈技術體系的技術關鍵點,技術細節。后續就算切換為其他的成熟的調用鏈產品,當使用中出現問題時,也能從原理層面分析問題。
- 自定義調用鏈插件在日志管理方面更靈活,便於后期業務日志分析,日志存儲切換方案等可以做出快速調整。
- 隨着Spring體系的升級,中間件的升級,自定義的調用鏈插件受到影響時,也需要升級。存在一定的維護成本。
- 在更加多元化的日志分析中,如權重管理,比例攔截日志等方面,自定義的插件都需要開發才能支持。
- 自定義插件的性能,技術實現方案與開發者掌握的技術密切相關。同開源的優秀調用鏈工具對比,肯定還是存在差異,需要開發者更新和替換。
五、案例源碼
參考完整實現代碼:https://github.com/wuya11/TraceDemo
運行截圖參考: