使用篇丨鍊路追蹤（Tracing）簡單：請求軌迹回溯與多元鍊路篩選

涯海 阿裡巴巴中間件 2023-03-31 13:44 發表于浙江

在日常生活中，我們可能都經曆過以下場景：去醫院看病就診，但預約頁面遲遲無法打開；新款手機釋出日促銷秒殺，下單頁面一直卡住轉菊花；遊戲大版本更新，線上人數過多，導緻人物一直在“漂移”。這些問題令産品體驗變得非常差，有耐心的同學還會吐槽幾句，沒耐心的同學早已轉身離開。試想一下，作為該系統開發/運維人員，又該如何避免此類問題發生，或者快速定位止損？

01

關鍵路徑與多條鍊路對比

Aliware

本章我們将以業務 Owner（小帥）的視角，逐漸了解分布式鍊路追蹤的各種基礎用法：小到單次使用者請求的異常根因診斷，大到全局系統的強弱依賴梳理，分布式鍊路追蹤都能給予确定性答案。

小帥作為一家電商公司訂單中心的業務 Owner，核心 KPI 就是保障建立訂單 createOrder 接口的可用性，如響應時延低于 3s，成功率大于 99.9%。一旦該接口可用性出現問題，會直接影響使用者下單行為，造成業務資損，進而影響小帥的績效和年終獎。

但建立訂單接口直接或間接依賴多個其他系統服務，如資金、位址、優惠、安全等。一旦某個下遊系統服務可用性出現問題，也會造成建立訂單失敗或逾時。為此，小帥特别頭痛，每當建立訂單接口不可用時，小帥都非常心急，卻不知該如何定位根因，隻能拉上所有下遊接口負責人一起評估，不僅費時費力，低效排查也造成業務損失進一步擴大，經常被老闆痛罵。

當小美了解這個情況後，推薦接入分布式鍊路追蹤系統，并通過一系列故障應急案例，指導如何利用 Tracing 定位問題，梳理風險，提前預警，切實提高了訂單中心的可用性。小帥經常會遇到各種使用者回報的建立訂單逾時問題，以往對此類問題頗有些束手無策。不過，接入分布式鍊路追蹤系統後，通過調用鍊準确回溯逾時請求的調用軌迹，小帥就可以輕松定位耗時最長的接口資訊，如下圖所示，A 接口逾時的主要原因是調用 D 接口導緻的。

但如果是下面這種情況，A 調用 B，B 又調用 C。那麼，導緻 A 接口逾時的根因到底是 B 接口，還是 C 接口呢？

為了區分真正影響使用者體驗的 Span 耗時，我們先來了解一下關鍵路徑的概念。

關鍵路徑

如果一次 Span 調用有 t 段耗時在關鍵路徑上，那麼去掉這 t 段耗時，整條鍊路的總體耗時也會相應的縮短 t 段時間。仍以上面那條鍊路為例，灰色部分表示關鍵路徑，縮短任意關鍵路徑上的耗時都可以減少整體耗時。此時，我們可以判斷 A 接口逾時的主要原因是 C 接口導緻的。

再來看另一種情況，如果 A 接口同一時間并行調用 B、C、D、E 接口，那麼耗時最長的 D 接口就成為關鍵路徑，如下圖所示。

但是，如果我們将 D 接口耗時減少 t1+t2 兩段時間，整體耗時卻隻減少了 t1 段時間，因為，當 D 接口耗時小于 B 接口時，D 接口就不再是關鍵路徑，而是由 B 接口取代。這就好像主要沖突被大幅緩解後，次要沖突就變成了主要沖突。

綜上所述，我們在做耗時性能分析時，應該首先識别出關鍵路徑，然後再做針對性的優化。對于非關鍵路徑上的耗時優化不會對最終的使用者體驗産生價值。

多條鍊路對比

單條調用鍊路隻能用來分析各個接口的絕對耗時，而無法得知每個接口的耗時變化情況。但是，絕對耗時長不代表這個接口就一定有問題，比如資料存儲接口耗時通常要比單純的計算接口耗時要長，這種長耗時是合理的，無需特别關注。

是以，在診斷性能退化問題時，我們更應該關注相對耗時的變化。比如擷取同一個接口在耗時異常時段與正常時段的多條鍊路進行比對，進而發現導緻性能退化的原因。下圖展示了 A 接口的兩條不同鍊路，我們可以清楚的看到，雖然第一條鍊路的 B 接口耗時要比 C 接口耗時長，但是導緻 A 接口整體耗時從 2.6s 漲到 3.6s 的原因，其實是 C 接口的相對耗時變長了 1s，而 B 接口的相對耗時幾乎不變。是以，當 A 接口的響應時延超過 3s，不滿足可用性要求時，我們應該優先分析 C 接口相對耗時增長的原因，而不是 B 接口。

我們再來看一個緩存未命中的例子，如下圖所示。第一條鍊路調用了5次資料庫，每一次調用的耗時都不算很長，但是 A 接口整體耗時卻達到了 3.6s。當我們比對之前未逾時的鍊路時，發現 A 接口并沒有調用資料庫，而是請求了5次緩存，整體耗時隻有 1.8s。此時，我們可以判斷 A 接口逾時的原因是調用依賴行為發生了變化，原本應該請求緩存的調用變成了請求資料庫，很可能是緩存被打滿，或者是該次請求的參數命中了冷資料，最終導緻了接口逾時。

通過上面兩個案例，我們認識到分析性能問題時，不僅需要知道絕對耗時的多少，更要關注相對耗時的變化。當然，有經驗的同學如果對自身業務的正常鍊路形态了若指掌，就可以直接觀察異常鍊路得出結論。

02

關聯資訊回溯

Aliware

通過前面的學習，小帥已經成功掌握了調用鍊的軌迹回溯能力，可以熟練運用調用鍊分析性能瓶頸點，快速定位異常的接口。但是，他又遇到了新的困惑，就是找到了異常接口之後，下一步該怎麼辦？比如 C 接口的耗時從 0.1s 增長到了 2.1s，導緻了上遊的 A 接口逾時。但是僅僅知道這個資訊還不夠，C 接口耗時增長背後的原因是什麼？如何解決這個問題，讓它恢複到原來的性能基線？

很多線上問題，很難隻通過接口粒度的鍊路資訊定位根因，需要結合更加豐富的關聯資料，指導下一步的行動。接下來，我們通過幾個案例，介紹幾類最典型的鍊路關聯資料，以及相應的用法。

本地方法棧

小帥負責的訂單系統，每天上午十點都會有一波周期性的業務峰值流量，偶爾出現一些逾時請求，但下遊調用耗時都很短，無法判斷逾時的具體原因，導緻這個問題一直懸而未決，為此小帥十分頭痛，隻好求助小美。正常請求與逾時請求的調用鍊路對比如下圖所示。

由于逾時請求鍊路的相對耗時增長主要是 A 接口本身，是以，小美建議小帥啟用慢調用方法棧自動剖析功能，自動抓取逾時請求的完整本地方法棧，如下圖所示。

通過本地方法棧，小帥得知逾時請求是卡在 log4j 日志架構 callAppenders 方法上，原來 log4j 在高并發場景的同步輸出會觸發 “熱鎖”現象，小帥将 log4j 的日志輸出由同步模式改為異步模式後，就解決了業務峰值逾時的問題。

如果小帥使用的分布式鍊路追蹤系統，并沒有提供慢調用方法棧自動剖析功能，也可以通過 Arthas 等線上診斷工具手動抓取方法棧，定位到異常方法後，再考慮将其添加至本地方法插樁埋點中，進行常态化追蹤。

自動關聯資料

基于分布式鍊路追蹤的架構攔截點，可以自動關聯多種類型的資料，比如接口請求的出/入參數，調用過程中抛出的異常堆棧，資料庫請求的執行 SQL 等等。此類資訊不影響調用鍊的形态，卻會極大的豐富鍊路的資訊，更明确的闡述為什麼會出現這樣或那樣狀況的原因。

比如小帥接到上遊業務方回報，某個新管道的商品下單總是逾時，經過排查後發現該管道訂單依賴的資料庫調用非常的慢，通過分析 SQL 明細才知道這個資料庫調用是擷取管道優惠資訊，但沒有做管道過濾，而是全量查詢了所有優惠規則，優化 SQL 查詢語句後逾時問題就解決了。

自動關聯資料通常由分布式鍊路追蹤産品預設提供，使用者根據自身的需要選擇是否開啟即可，無需額外的操作成本。一般情況下，SQL明細和異常堆棧關聯建議常态化開啟，而記錄請求出/入參數需要消耗較大的系統開銷，建議預設關閉，僅在需要的時候臨時開啟。

主動關聯資料

小帥的老闆希望能夠定期分析來自不同管道、不同品類、不同使用者類型的訂單情況，并且将訂單接口異常排查的能力向一線營運小二開放賦能，提高使用者支援效率。正在小帥一籌莫展之際，小美建議小帥将業務資訊關聯至調用鍊上，提供業務标簽統計、業務日志軌迹排查等能力。

小帥聽取了小美的建議後，首先将管道、品類、使用者類型等業務标簽添加到分布式鍊路追蹤的 Attributes 對象中，這樣就可以分别統計不同标簽的流量趨勢，時延分布和錯誤率變化；其次，小帥将業務日志也關聯到分布式鍊路追蹤的 Event 對象中，這樣就可以檢視一次訂單請求在不同系統中的業務軌迹與資訊，即使是不懂技術的營運同學也能夠清晰的判斷問題原因，更有效的支援客戶，如下圖所示。

由于業務邏輯千變萬化，無法窮舉，是以業務資料需要使用者主動進行關聯，分布式鍊路追蹤系統僅能簡化關聯過程，無法實作完全自動化。此外，自定義标簽和業務日志是最常用的兩種主動關聯資料類型，可以有效地将調用鍊的确定性關聯能力擴充至業務領域，解決業務問題。

綜合分析

通過本小節的學習，相信大家已經非常熟悉分布式鍊路追蹤的請求軌迹回溯能力，我們再來整體回顧一下：首先調用鍊提供了接口次元的軌迹追蹤，而本地方法棧可以較長的描述某個接口内部的代碼執行情況，自動關聯資料和主動關聯資料在不改變鍊路形态的前提下，極大的豐富了鍊路資訊，有效指導我們下一步的行動。在一些比較複雜的問題場景，需要結合以上資訊進行多角度的綜合判斷，如下圖所示。

上一小節我們介紹了如何通過調用鍊和關聯資訊進行問題診斷，但是，細心的讀者可能會有一個疑問，整個系統有那麼多的調用鍊，我怎麼知道哪條鍊路才是真正描述我在排查的這個問題？如果找到了不相符的鍊路豈不是會南轅北轍？

沒錯！在使用調用鍊分析問題之前，還有一個很重要的步驟，就是從海量鍊路資料中，通過各種條件篩選出真實反應目前問題的調用鍊，這個動作就叫做鍊路篩選。那什麼叫多元呢？多元是指通過 TraceId、鍊路特征或自定義标簽等多種次元進行鍊路篩選。每一種篩選條件都是由日常開發/運維的場景演變而來，最為契合當下的使用方式，提高了鍊路篩選的效率和精準度。

03

多元度鍊路篩選

Aliware

（一）基于鍊路辨別 TraceId 的篩選

提到鍊路篩選，大家很自然的就會想到使用全局鍊路唯一辨別 TraceId 進行過濾，這是最精準、最有效的一種辦法。但是，TraceId 從哪裡來？我該如何擷取呢？

如何擷取 TraceId？

雖然TraceId 貫穿于整個 IT 系統，隻不過大部分時候，它隻是默默配合上下文承擔着鍊路傳播的職責，沒有顯式的暴露出來。常見的 TraceId 擷取方式有以下幾種:

• 前端請求 Header 或響應體 Response：大部分使用者請求都是在端上裝置發起的，是以 TraceId 生成的最佳地點也是在端上裝置，通過請求 Header 透傳給後端服務。是以，我們在通過浏覽器開發者模式調試時，就可以擷取目前測試請求 Header 中的 TraceId 進行篩選。如果端上裝置沒有接入分布式鍊路追蹤埋點，也可以将後端服務生成的 TraceId 添加到 Response 響應體中傳回給前端。這種方式非常适合前後端聯調場景，可以快速找到每一次點選對應的 TraceId，進而分析行為背後的鍊路軌迹與狀态。
• 網關日志：網關是所有使用者請求發往後端服務的代理中轉站，可以視為後端服務的入口。在網關的 access.log 通路日志中添加 TraceId，可以幫助我們快速分析每一次異常通路的軌迹與原因。比如一個逾時或錯誤請求，到底是網關自身的原因，還是後端某個服務的原因，可以通過調用鍊中每個 Span 的狀态得到确定性的結論。
• 應用日志：應用日志可以說是我們最熟悉的一種日志，我們會将各種業務或系統的行為、中間狀态和結果，在開發編碼的過程中順手記錄到應用日志中，使用起來非常友善。同時，它也是可讀性最強的一類日志，即使是非開發運維人員也能大緻了解應用日志所表達的含義。是以，我們可以将 TraceId 也記錄到應用日志中進行關聯，一旦出現某種業務異常，我們可以先通過目前應用的日志定位到報錯資訊，再通過關聯的 TraceId 去追溯該應用上下遊依賴的其他資訊，最終定位到導緻問題出現的根因節點。
• 元件日志：在分布式系統中，大部分應用都會依賴一些外部元件，比如資料庫、消息、配置中心等等。這些外部元件也會經常發生這樣或那樣的異常，最終影響應用服務的整體可用性。但是，外部元件通常是共用的，有專門的團隊進行維護，不受應用 Owner 的控制。是以，一旦出現問題，也很難形成有效的排查回路。此時，我們可以将 TraceId 透傳給外部元件，并要求他們在自己的元件日志中進行關聯，同時開放元件日志查詢權限。舉個例子，我們可以通過 SQL Hint 傳播鍊 TraceId，并将其記錄到資料庫服務端的 Binlog 中，一旦出現慢 SQL 就可以追溯資料庫服務端的具體表現，比如一次請求記錄數過多，查詢語句沒有建索引等等。

如何在日志中關聯 TraceId？

既然 TraceId 關聯有這麼多的好處，那麼我們如何在日志輸出時添加 TraceId 呢？主要有兩種方式：

• 基于 SDK 手動埋點：鍊路透傳的每個節點都可以擷取目前調用生命周期内的上下文資訊。最基礎的關聯方式就是通過 SDK 來手動擷取 TraceId，将其作為參數添加至業務日志的輸出中。
• 基于日志模闆自動埋點：如果一個存量應用有大量日志需要關聯 TraceId，一行行的修改代碼添加 TraceId 的改造成本屬實有點高，也很難被執行下去。是以，比較成熟的 Tracing 實作架構會提供一種基于日志模闆的自動埋點方式，無需修改業務代碼就可以在業務日志中批量注入 TraceId，使用起來極為友善。

基于 SDK 手動實作日志與 TraceId 關聯示例

以 Jaeger Java SDK 為例，手動埋點主要分為以下幾步：

1. 打開應用代碼工程的 pom.xml 檔案，添加對 Jaeger 用戶端的依賴（正常情況下該依賴已經被添加，可以跳過）。

<dependency>    
    <groupId>io.jaegertracing</groupId>     
    <artifactId>jaeger-client</artifactId>     
    <version>0.31.0</version> 
</dependency>           

2. 在日志輸出代碼前面，先擷取目前調用生命周期的 Span 對象，再從上下文中擷取 TraceId 辨別。

String traceId = GlobalTracer.get().activeSpan().context().toTraceId();           

3. 将 TraceId 添加到業務日志中一并輸出。

log.error("fail to create order, traceId: {}", traceId);           

4. 最終的日志效果如下所示，這樣我們就可以根據業務關鍵詞先過濾日志，再通過關聯的 TraceId 查詢上下遊全鍊路軌迹的資訊。

fail to create order, traceId: ee14662c52387763           

基于日志模闆實作日志與 TraceId 自動關聯示例

基于 SDK 手動埋點需要一行行的修改代碼，無疑是非常繁瑣的，如果需要在日志中批量添加 TraceId，可以采用日志模闆注入的方式。

目前大部分的日志架構都支援 Slf4j 日志門面，它提供了一種 MDC（Mapped Dignostic Contexts）機制，可以在多線程場景下線程安全的實作使用者自定義标簽的動态注入。

MDC 的使用方法很簡單，隻需要兩步。

第一步，我們先通過 MDC 的 put 方法将自定義标簽添加到診斷上下文中：

@Test 
public void testMDC() {     
  MDC.put("userName", "xiaoming");     
  MDC.put("traceId", GlobalTracer.get().activeSpan().context().toTraceId());     
  log.info("Just test the MDC!"); 
}           

第二步，在日志配置檔案的 Pattern 描述中添加标簽變量 %X{userName} 和 %X{traceId}。

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">     
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">         
        <level>INFO</level>     
    </filter>     
    <encoder>         
        <pattern>%d{HH:mm:ss} [%thread] %-5level [userName=%X{userName}] [traceId=%X{traceId}] %msg%n</pattern>         
        <charset>utf-8</charset>     
    </encoder> 
</appender>           

這樣，我們就完成了 MDC 變量注入的過程，最終日志輸出效果如下所示：

15:17:47 [http-nio-80-exec-1] INFO [userName=xiaoming] [traceId=ee14662c52387763] Just test the MDC!           

看到這裡，細心的讀者可能會疑問，MDC 注入不是也需要修改代碼麼？答案是确實需要，不過好在 Tracing 架構已經提供了簡易的關聯方式，無需逐行修改日志代碼，極大的減少了改造量。比如 Jaeger SDK 提供了 MDCScopeManager 對象，隻需要在建立 Tracer 對象時順便關聯上 MDCScopeManager 就可以實作 traceId、spanId 和 sampled 自動注入到 MDC 上下文中，如下所示：

MDCScopeManager scopeManager = new MDCScopeManager.Builder().build(); 
JaegerTracer tracer = new JaegerTracer.Builder("serviceName").withScopeManager(scopeManager).build();           

通過 MDC 機制，有效推動了實際生産環境中應用日志與 Trace 鍊路的關聯，你也快動手試試吧。

日志關聯 TraceId 的限制有哪些？

并不是所有日志都能夠與 TraceId 進行關聯，最根本的原因就是在日志輸出的時機找不到相對應的鍊路上下文，這是怎麼回事呢？

原來，鍊路上下文僅在調用周期内才存在，一旦調用結束，或者尚未開始，又或者由于異步線程切換導緻上下文丢失等場景，都會無法擷取鍊路上下文，也就無法與日志進行關聯了。比如，在應用啟動階段，許多對象的初始化動作都不在請求處理主邏輯中，強行關聯 TraceId 隻會擷取到一個空值。

是以，在實際應用中，如果發現無法在應用日志中輸出 TraceId，可以逐一檢查以下幾點：

1. 确認類似 MDCScopeManager 初始化的變量注入工作是否完成？
2. 确認日志模闆中是否添加 %X{traceId} 變量？
3. 确認目前日志是否在某個調用的生命周期内部，且確定鍊路上下文不會因為異步線程切換導緻丢失。

綜上所述，我們可以在系統報錯時，快速找到關聯的 TraceId，再進行整條鍊路的軌迹資訊回溯，最終定位根因解決問題。但是，如果我們由于各種限制還沒有完成 TraceId 的關聯，那麼該怎麼辦呢？接下來我們來介紹兩種不需要 TraceId 的篩選方法。

（二）基于鍊路特征的篩選

鍊路特征是指調用鍊本身所具備的一些基礎資訊，比如接口名稱，請求狀态，響應耗時，節點IP、所屬應用等等。這些基礎資訊被廣泛應用于各類監控、告警系統。一旦應用出現異常，會根據統計資料先判斷出大緻的問題影響面，比如在哪個應用，哪個接口，是變慢了還是錯誤率升高了？

然後，再根據這些基礎資訊組合篩選出滿足條件的調用鍊路，例如：

serviceName=order AND spanName=createOrder AND duration>5s           

這樣，我們就可以過濾出應用名稱為 order，接口名稱為 createOrder，請求耗時大于 5秒的一組調用鍊路，再結合上一小節學習的單鍊路或多鍊路軌迹回溯分析，就可以輕松定位問題根因。

（三）基于自定義标簽的篩選

在排查某些業務問題時，鍊路特征無法實作調用鍊的精準篩選。比如下單接口的來源管道可以細分為線上門店、線下批發、線下零售、直播管道、三方推廣等等。如果我們需要準确分析某個新管道的鍊路問題，需要結合自定義标簽來篩選。

小帥所在的公司新拓展了線下零售模式，作為集團戰略，需要重點保障線下零售管道的訂單接口可用性。是以，小帥在下單接口的鍊路上下文中添加了管道（channel）标簽，如下所示：

@GetMapping("/createOrder") 
public ApiResponse createOrder(@RequestParam("orderId") String orderId, @RequestParam("channel") String channel) { 
... 
// 在鍊路上下文中添加管道标簽 
GlobalTracer.get().activeSpan().setTag("channel", channel); 
... 
}           

每當線下零售同學回報訂單接口異常時，小帥就可以根據 channel 标簽精準過濾出滿足條件的調用鍊路，快速定位異常根因，如下所示：

serviceName=order AND spanName=createOrder AND duration>5s AND attributes.channel=offline_retail           

（四）一個典型的鍊路診斷示例

本小節我們介紹了三種不同的鍊路篩選方式，結合上一小節的請求軌迹回溯，我們來看一個典型的鍊路篩選與診斷過程，主要分為以下幾步：

1. 根據 TraceId、應用名、接口名、耗時、狀态碼、自定義标簽等任意條件組合過濾出目标調用鍊。
2. 從滿足過濾條件的調用鍊清單中選中一條鍊路查詢詳情。
3. 結合請求調用軌迹，本地方法棧，主動/自動關聯資料（如SQL、業務日志）綜合分析調用鍊。
4. 如果上述資訊仍無法定位根因，需要結合記憶體快照、Arthas 線上診斷等工具進行二次分析。

04

預告

Aliware

在完整介紹分布式鍊路追蹤的前世今生及基礎概念之後，本文了解了請求軌迹回溯、多元鍊路篩選場景，接下來的章節我們将繼續介紹：

• 鍊路實時分析、監控與告警
• 鍊路拓撲

更多内容，敬請期待！