Spring Cloud構建微服務架構：分佈式服務跟蹤（收集原理）【Dalston版】

在本節內容以前，咱們已經對如何引入Sleuth跟蹤信息和搭建Zipkin服務端分析跟蹤延遲的過程作了詳細的介紹，相信你們對於Sleuth和Zipkin已經有了必定的感性認識。接下來，咱們介紹一下關於Zipkin收集跟蹤信息的過程細節，以幫助咱們更好地理解Sleuth生產跟蹤信息以及輸出跟蹤信息的總體過程和工做原理。

數據模型

咱們先來看看Zipkin中關於跟蹤信息的一些基礎概念。因爲Zipkin的實現借鑑了Google的Dapper，因此它們有着相似的核心術語，主要有下面幾個內容：

• Span：它表明了一個基礎的工做單元。咱們以HTTP請求爲例，一次完整的請求過程在客戶端和服務端都會產生多個不一樣的事件狀態（好比下面所說的四個核心Annotation所標識的不一樣階段），對於同一個請求來講，它們屬於一個工做單元，因此同一HTTP請求過程當中的四個Annotation同屬於一個Span。每個不一樣的工做單元都經過一個64位的ID來惟一標識，稱爲Span ID。另外，在工做單元中還存儲了一個用來串聯其餘工做單元的ID，它也經過一個64位的ID來惟一標識，稱爲Trace ID。在同一條請求鏈路中的不一樣工做單元都會有不一樣的Span ID，可是它們的Trace ID是相同的，因此經過Trace ID能夠將一次請求中依賴的全部依賴請求串聯起來造成請求鏈路。除了這兩個核心的ID以外，Span中還存儲了一些其餘信息，好比：描述信息、事件時間戳、Annotation的鍵值對屬性、上一級工做單元的Span ID等。
• Trace：它是由一系列具備相同Trace ID的Span串聯造成的一個樹狀結構。在複雜的分佈式系統中，每個外部請求一般都會產生一個複雜的樹狀結構的Trace。

• Annotation：它用來及時地記錄一個事件的存在。咱們能夠把Annotation理解爲一個包含有時間戳的事件標籤，對於一個HTTP請求來講，在Sleuth中定義了下面四個核心Annotation來標識一個請求的開始和結束：

  • cs（Client Send）：該Annotation用來記錄客戶端發起了一個請求，同時它也標識了這個HTTP請求的開始。
  • sr（Server Received）：該Annotation用來記錄服務端接收到了請求，並準備開始處理它。經過計算sr與cs兩個Annotation的時間戳之差，咱們能夠獲得當前HTTP請求的網絡延遲。
  • ss（Server Send）：該Annotation用來記錄服務端處理完請求後準備發送請求響應信息。經過計算ss與sr兩個Annotation的時間戳之差，咱們能夠獲得當前服務端處理請求的時間消耗。
  • cr（Client Received）：該Annotation用來記錄客戶端接收到服務端的回覆，同時它也標識了這個HTTP請求的結束。經過計算cr與cs兩個Annotation的時間戳之差，咱們能夠獲得該HTTP請求從客戶端發起開始到接收服務端響應的總時間消耗。
• BinaryAnnotation：它用來對跟蹤信息添加一些額外的補充說明，通常以鍵值對方式出現。好比：在記錄HTTP請求接收後執行具體業務邏輯時，此時並無默認的Annotation來標識該事件狀態，可是有BinaryAnnotation信息對其進行補充。

收集機制

在理解了Zipkin的各個基本概念以後，下面咱們結合前面章節中實現的例子來詳細介紹和理解Spring Cloud Sleuth是如何對請求調用鏈路完成跟蹤信息的生產、輸出和後續處理的。

首先，咱們來看看Sleuth在請求調用時是怎麼樣來記錄和生成跟蹤信息的。下圖展現了咱們在本章節中實現示例的運行全過程：客戶端發送了一個HTTP請求到trace-1，trace-1依賴於trace-2的服務，因此trace-1再發送一個HTTP請求到trace-2，待trace-2返回響應以後，trace-1再組織響應結果返回給客戶端。

在上圖的請求過程當中，咱們爲整個調用過程標記了10個標籤，它們分別表明了該請求鏈路運行過程當中記錄的幾個重要事件狀態，咱們根據事件發生的時間順序咱們爲這些標籤作了從小到大的編號，1表明請求的開始、10表明請求的結束。每一個標籤中記錄了一些咱們上面提到過的核心元素：Trace ID、Span ID以及Annotation。因爲這些標籤都源自一個請求，因此他們的Trace ID相同，而標籤1和標籤10是起始和結束節點，它們的Trace ID與Span ID是相同的。

根據Span ID，咱們能夠發如今這些標籤中一共產生了4個不一樣ID的Span，這4個Span分別表明了這樣4個工做單元：

• Span T：記錄了客戶端請求到達trace-1和trace-1發送請求響應的兩個事件，它能夠計算出了客戶端請求響應過程的總延遲時間。
• Span A：記錄了trace-1應用在接收到客戶端請求以後調用處理方法的開始和結束兩個事件，它能夠計算出trace-1應用用於處理客戶端請求時，內部邏輯花費的時間延遲。
• Span B：記錄了trace-1應用發送請求給trace-2應用、trace-2應用接收請求，trace-2應用發送響應、trace-1應用接收響應四個事件，它能夠計算出trace-1調用trace-2的整體依賴時間（cr - cs），也能夠計算出trace-1到trace-2的網絡延遲（sr - cs），也能夠計算出trace-2應用用於處理客戶端請求的內部邏輯花費的時間延遲（ss - sr）。
• Span C：記錄了trace-2應用在接收到trace-1的請求以後調用處理方法的開始和結束兩個事件，它能夠計算出trace-2應用用於處理來自trace-1的請求時，內部邏輯花費的時間延遲。

在圖中展示的這個4個Span正好對應了Zipkin查看跟蹤詳細頁面中的顯示內容，它們的對應關係以下圖所示：

仔細的讀者可能還有這樣一個疑惑：咱們在Zipkin服務端查詢跟蹤信息時（以下圖所示），在查詢結果頁面中顯示的spans是5，而點擊進入跟蹤明細頁面時，顯示的Total Spans又是4，爲何會出現span數量不一致的狀況呢？

實際上這兩邊的span數量內容有不一樣的含義，在查詢結果頁面中的5 spans表明了總共接收的Span數量，而在詳細頁面中的Total Span則是對接收Span進行合併後的結果，也就是前文中咱們介紹的4個不一樣ID的Span內容。下面咱們來詳細研究一下Zipkin服務端收集客戶端跟蹤信息的過程，看看它到底收到了哪些具體的Span內容，從而來理解Zipkin中收集到的Span總數量。

爲了更直觀的觀察Zipkin服務端的收集過程，咱們能夠對以前實現的消息中間件方式收集跟蹤信息的程序進行調試。經過在Zipkin服務端的消息通道監聽程序中增長斷點，咱們就能清楚的知道客戶端都發送了一些什麼信息到Zipkin的服務端。在spring-cloud-sleuth-zipkin-stream依賴包中的代碼並很少，咱們很容易的就能找到定義消息通道監聽的實現類：org.springframework.cloud.sleuth.zipkin.stream.ZipkinMessageListener。它的具體實現以下所示，其中SleuthSink.INPUT定義了監聽的輸入通道，默認會使用名爲sleuth的主題，咱們也能夠經過Spring Cloud Stream的配置對其進行修改。

@MessageEndpoint
@Conditional(NotSleuthStreamClient.class)
public class ZipkinMessageListener {
  
      final Collector collector;

      @ServiceActivator(inputChannel = SleuthSink.INPUT)
    public void sink(Spans input) {
        List<zipkin.Span> converted = ConvertToZipkinSpanList.convert(input);
        this.collector.accept(converted, Callback.NOOP);
    }
    
    ...

}

從通道監聽方法的定義中咱們能夠看到Sleuth與Zipkin在整合的時候是有兩個不一樣的Span定義的，一個是消息通道的輸入對象org.springframework.cloud.sleuth.stream.Spans，它是sleuth中定義的用於消息通道傳輸的Span對象，每一個消息中包含的Span信息定義在org.springframework.cloud.sleuth.Span對象中，可是真正在zipkin服務端使用的並不是這個Span對象，而是zipkin本身的zipkin.Span對象。因此，在消息通道監聽處理方法中，對sleuth的Span作了處理，每次接收到sleuth的Span以後就將其轉換成Zipkin的Span。

下面咱們能夠嘗試在sink(Spans input)方法實現的第一行代碼中加入斷點，並向trace-1發送一個請求，觸發跟蹤信息發送到RabbitMQ上。此時咱們經過DEBUG模式能夠發現消息通道中都接收到了兩次輸入，一次來自trace-1，一次來自trace-2。下面兩張圖分別展現了來自trace-1和trace-2輸出的跟蹤消息，其中trace-1的跟蹤消息包含了3條span信息，trace-2的跟蹤消息包含了2條span信息，因此在這個請求調用鏈上，一共發送了5個span信息，也就是咱們在Zipkin搜索結果頁面中看到的spans數量信息。

點開一個具體的Span內容，咱們能夠看到以下所示的結構，它記錄了Sleuth中定義的Span詳細信息，包括該Span的開始時間、結束時間、Span的名稱、Trace ID、Span ID、Tags（對應Zipkin中的BinaryAnnotation）、Logs（對應Zipkin中的Annotation）等咱們以前提到過的核心跟蹤信息。

介紹到這裏仔細的讀者可能會有一個這樣的疑惑，在明細信息中展現的Trace ID和Span ID的值爲何與列表展現的概要信息中的Trace ID和Span ID的值不同呢？實際上，Trace ID和Span ID都是使用long類型存儲的，在DEBUG模式下查看其明細時天然是long類型，也就是它的原始值，可是在查看Span對象的時候，咱們看到的是經過toString()函數處理過的值，從sleuth的Span源碼中咱們能夠看到以下定義，在輸出Trace ID和Span ID時都調用了idToHex函數將long類型的值轉換成了16進制的字符串值，因此在DEBUG時咱們會看到兩個不同的值。

public String toString() {
    return "[Trace: " + idToHex(this.traceId) + ", Span: " + idToHex(this.spanId)
            + ", Parent: " + getParentIdIfPresent() + ", exportable:" + this.exportable + "]";
}

public static String idToHex(long id) {
    return Long.toHexString(id);
}

在接收到Sleuth以後咱們將程序繼續執行下去，能夠看到通過轉換後的Zipkin的Span內容，它們保存在一個名爲converted的列表中，具體內容以下所示：

上圖展現了轉換後的Zipkin Span對象的詳細內容，咱們能夠看到不少熟悉的名稱，也就是以前咱們介紹的關於zipkin中的各個基本概念，而這些基本概念的值咱們也均可以在以前sleuth的原始span中找到，其中annotations和binaryAnnotations有一些特殊，在sleuth定義的span中沒有使用相同的名稱，而是使用了logs和tags來命名。從這裏的詳細信息中，咱們能夠直觀的看到annotations和binaryAnnotations的做用，其中annotations中存儲了當前Span包含的各類事件狀態以及對應事件狀態的時間戳，而binaryAnnotations則存儲了對事件的補充信息，好比上圖中存儲的就是該HTTP請求的細節描述信息，除此以外，它也能夠存儲對調用函數的詳細描述（以下圖所示）。

下面咱們再來詳細看看經過調試消息監聽程序接收到的這5個Span內容。首先，咱們能夠發現每一個Span中都包含有3個ID信息，其中除了標識Span自身的ID以及用來標識整條鏈路的traceId以外，還有一個以前沒有提過的parentId，它是用來標識各Span父子關係的ID（它的值來自與上一步執行單元Span的ID） ，經過parentId的定義咱們能夠爲每一個Span找到它的前置節點，從而定位每一個Span在請求調用鏈中的確切位置。在每條調用鏈路中都有一個特殊的Span，它的parentId爲null，這類Span咱們稱它爲Root Span，也就是這條請求調用鏈的根節點。爲了弄清楚這些Span之間的關係，咱們能夠從Root Span開始來整理出整條鏈路的Span內容。下表展現了咱們從Root Span開始，根據各個Span的父子關係最後整理出的結果：

Host	Span ID	Parent Span ID	Annotation	Binary Annotation
trace-1	e9a933ec50d180d6	null	[sr, ss]
trace-1	c48122fa096bffe8	e9a933ec50d180d6		[trace-1,TraceApplication,trace]
trace-1	1ae2e9a317faa422	c48122fa096bffe8	[cs, cr]
trace-2	1ae2e9a317faa422	c48122fa096bffe8	[sr, ss]
trace-2	36194e4182985c4e	1ae2e9a317faa422		[trace-2,TraceApplication,trace]

上表中的Host表明了該Span是從哪一個應用發送過來的；Span ID是當前Span的惟一標識；Parent Span ID表明了上一執行單元的Span ID；Annotation表明了該Span中記錄的事件（這裏主要用來記錄HTTP請求的四個階段，表中內容做了省略處理，只記錄了Annotation名稱（sr表明服務端接收請求，ss表明服務端發送請求，cs表明客戶端發送請求，cr表明客戶端接收請求），省略了一些其餘細節信息，好比服務名、時間戳、IP地址、端口號等信息）；Binary Annotation表明了事件的補充信息（Sleuth的原始Span記錄更爲詳細，Zipkin的Span處理後會去掉一些內容，對於有Annotation標識的信息，再也不使用Binary Annotation補充，在上表中咱們只記錄了服務名、類名、方法名，一樣省略了一些其餘信息，好比：時間戳、IP地址、端口號等信息）。

經過收集到的Zipkin Span詳細信息，咱們很容易的能夠將它們與本節開始時介紹的一次調用鏈路中的10個標籤內容聯繫起來：

• Span ID = T的標籤有2個，分別是序號1和10，它們分別表示此次請求的開始和結束。它們對應了上表中ID爲e9a933ec50d180d6的Span，該Span的內容在標籤10執行結束後，由trace-1將標籤1和10合併成一個Span發送給Zipkin Server。
• Span ID = A的標籤有2個，分別是序號2和9，它們分別表示了trace-1請求接收後，具體處理方法調用的開始和結束。該Span的內容在標籤9執行結束後，由trace-1將標籤2和9合併成一個Span發送給Zipkin Server。
• Span ID = B的標籤有4個，分別是序號三、四、七、8，該Span比較特殊，它的產生跨越了兩個實例，其中標籤3和8是由trace-1生成的，而標籤4和7則是由trace-2生成的，因此該標籤會拆分紅兩個Span內容發送給Zipkin Server。trace-1會在標籤8結束的時候將標籤3和8合併成一個Span發送給Zipkin Server，而trace-2會在標籤7結束的時候將標籤4和7合併成一個Span發送給Zipkin Server。
• Span ID = C的標籤有2個，分別是序號5和6，它們分別表示了trace-2請求接收後，具體處理方法調用的開始和結束。該Span的內容在標籤6執行結束後，由trace-2將標籤2和9合併成一個Span發送給Zipkin Server。

因此，根據上面的分析，Zipkin總共會收到5個Span：一個Span T，一個Span A，兩個Span B，一個Span C。結合以前請求鏈路的標籤圖和這裏的Span記錄，咱們能夠總結出以下圖所示的Span收集過程，讀者能夠參照此圖來理解Span收集過程的處理邏輯以及各個Span之間的關係。

雖然，Zipkin服務端接收到了5個Span，但就如前文中分析的那樣，其中有兩個Span ID=B的標籤，因爲它們來自於同一個HTTP請求（trace-1對trace-2的服務調用），概念上它們屬於同一個工做單元，所以Zipkin服務端在前端展示分析詳情時會將這兩個Span合併了來顯示，而合併後的Span數量就是在請求鏈路詳情頁面中Total Spans的數量。

下圖是本章示例的一個請求鏈路詳情頁面，在頁面中顯示了各個Span的延遲統計，其中第三條Span信息就是trace-1對trace-2的HTTP請求調用，經過點擊它能夠查看該Span的詳細信息，點擊後會以模態框的方式彈出Span詳細信息（如圖下半部分），在彈出框中詳細展現了Span的Annotation和BinaryAnnotation信息，在Annotation區域咱們能夠看到它同時包含了trace-1和trace-2發送的Span信息，而在BinaryAnnotation區域則展現了該HTTP請求的詳細信息。

原文地址： http://blog.didispace.com/spr...

完整示例：

讀者能夠根據喜愛選擇下面的兩個倉庫中查看trace-1和trace-2兩個項目：

• Github：https://github.com/dyc87112/SpringCloud-Learning/
• Gitee：https://gitee.com/didispace/SpringCloud-Learning/

若是您對這些感興趣，歡迎star、follow、收藏、轉發給予支持！

本文內容部分節選自個人《Spring Cloud微服務實戰》，但對依賴的Spring Boot和Spring Cloud版本作了升級。