一、技術原理
1.1 背景
微服務架構是一個分布式架構,它按業務劃分服務單元,一個分布式系統往往有很多個服務單元,由于服務單元數量眾多,業務的復雜性,如果出現了錯誤和例外,很難去定位,主要體現在,一個請求可能需要呼叫很多個服務,而內部服務的呼叫復雜性,決定了問題難以定位,所以微服務架構中,必須實作分布式鏈路追蹤,去跟進一個請求到底有哪些服務參與,參與的順序又是怎樣的,從而達到每個請求的步驟清晰可見,出了問題,很快定位,
舉個例子,在微服務系統中,一個來自用戶的請求,請求先達到前端A(如前端界面),然后通過遠程呼叫,達到系統的中間件B、C(如負載均衡、網關等),最后達到后端服務D、E,后端經過一系列的業務邏輯計算最后將資料回傳給用戶,對于這樣一個請求,經歷了這么多個服務,怎么樣將它的請求程序的資料記錄下來呢?這就需要用到服務鏈路追蹤,
Google開源的 Dapper鏈路追蹤組件,并在2010年發表了論文《Dapper, a Large-Scale Distributed Systems Tracing Infrastructure》,這篇文章是業內實作鏈路追蹤的標桿和理論基礎,具有非常大的參考價值,
中文翻譯參考:http://bigbully.github.io/Dapper-translation/
目前,鏈路追蹤組件有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;
// 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" }View Code
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的生成和清空;
- 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(); } }View Code
- 獲取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(); } }View Code 該方案是把呼叫鏈編碼通過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(); } } }View Code 執行緒池傳遞編碼 主執行緒中記錄的呼叫鏈資訊通過執行緒池執行時,子執行緒會獲取不到主執行緒的呼叫鏈資訊(子執行緒獲取traceId為null),因此,需要在子執行緒執行時,主執行緒向子執行緒傳遞呼叫鏈相關編碼資訊,參考檔案: 多執行緒相關知識:多執行緒-JUC執行緒池 Spring 回呼方法裝飾器:多執行緒呼叫如何傳遞背景關系 JDK原生擴展Callable,Runnable:traceId跟蹤請求全流程日志 其他方法:Transmittable ThreadLocal(TTL) 支持快取執行緒池的 ThreadLocal
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(); } } }View Code
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" }View Code 服務A對應spanLog
- 服務A本身具備一個span節點資訊,且服務A的spanId,為sub_spans的parentSpanId,因為服務A通過Feign呼叫了一次服務B,記錄中間件的Span資訊一次,(呼叫多少次,記錄多少個孩子span節點,)
- 孩子節點的span資訊,內部的開始請求時間,結束請求時間,小于上級節點的起止時間,
- 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" }View Code 服務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" }View Code 服務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" }View Code
四、自實作方案優缺點
- 自定義一個呼叫鏈插件,便于根據專案需求,充分的定制化開發,
- 結合公司專案的需求,調整呼叫鏈方案,在呼叫鏈模塊成熟后,可做為中間件模塊,應用于公司的其他專案;
- 實作一個呼叫鏈插件,有利于了解整個呼叫鏈技術體系的技術關鍵點,技術細節,后續就算切換為其他的成熟的呼叫鏈產品,當使用中出現問題時,也能從原理層面分析問題,
- 自定義呼叫鏈插件在日志管理方面更靈活,便于后期業務日志分析,日志存盤切換方案等可以做出快速調整,
- 隨著Spring體系的升級,中間件的升級,自定義的呼叫鏈插件受到影響時,也需要升級,存在一定的維護成本,
- 在更加多元化的日志分析中,如權重管理,比例攔截日志等方面,自定義的插件都需要開發才能支持,
- 自定義插件的性能,技術實作方案與開發者掌握的技術密切相關,同開源的優秀呼叫鏈工具對比,肯定還是存在差異,需要開發者更新和替換,
五、案例原始碼
參考完整實作代碼:https://github.com/wuya11/TraceDemo
運行截圖參考:




轉載請註明出處,本文鏈接:https://www.uj5u.com/houduan/256606.html
標籤:Java
上一篇:(二)MyBatis從入門到入土——開發一個Mybatis專案
下一篇:mysql進階學習二之搭建主從
