在本節内容之前,我們已經對如何引入Sleuth跟蹤資訊和搭建Zipkin服務端分析跟蹤延遲的過程做了詳細的介紹,相信大家對于Sleuth和Zipkin已經有了一定的感性認識。接下來,我們介紹一下關于Zipkin收集跟蹤資訊的過程細節,以幫助我們更好地了解Sleuth生産跟蹤資訊以及輸出跟蹤資訊的整體過程和工作原理。
資料模型
我們先來看看Zipkin中關于跟蹤資訊的一些基礎概念。由于Zipkin的實作借鑒了Google的Dapper,是以它們有着類似的核心術語,主要有下面幾個内容:
-
:它代表了一個基礎的工作單元。我們以HTTP請求為例,一次完整的請求過程在用戶端和服務端都會産生多個不同的事件狀态(比如下面所說的四個核心Span
所辨別的不同階段),對于同一個請求來說,它們屬于一個工作單元,是以同一HTTP請求過程中的四個Annotation
同屬于一個Span。每一個不同的工作單元都通過一個64位的ID來唯一辨別,稱為Span ID。另外,在工作單元中還存儲了一個用來串聯其他工作單元的ID,它也通過一個64位的ID來唯一辨別,稱為Trace ID。在同一條請求鍊路中的不同工作單元都會有不同的Span ID,但是它們的Trace ID是相同的,是以通過Trace ID可以将一次請求中依賴的所有依賴請求串聯起來形成請求鍊路。除了這兩個核心的ID之外,Span中還存儲了一些其他資訊,比如:描述資訊、事件時間戳、Annotation的鍵值對屬性、上一級工作單元的Span ID等。Annotation
-
:它是由一系列具有相同Trace ID的Span串聯形成的一個樹狀結構。在複雜的分布式系統中,每一個外部請求通常都會産生一個複雜的樹狀結構的Trace。Trace
-
:它用來及時地記錄一個事件的存在。我們可以把Annotation了解為一個包含有時間戳的事件标簽,對于一個HTTP請求來說,在Sleuth中定義了下面四個核心Annotation來辨別一個請求的開始和結束:Annotation
-
-
(Client Send):該Annotation用來記錄用戶端發起了一個請求,同時它也辨別了這個HTTP請求的開始。cs
-
(Server Received):該Annotation用來記錄服務端接收到了請求,并準備開始處理它。通過計算sr
與sr
兩個Annotation的時間戳之差,我們可以得到目前HTTP請求的網絡延遲。cs
-
(Server Send):該Annotation用來記錄服務端處理完請求後準備發送請求響應資訊。通過計算ss
ss
兩個Annotation的時間戳之差,我們可以得到目前服務端處理請求的時間消耗。sr
-
(Client Received):該Annotation用來記錄用戶端接收到服務端的回複,同時它也辨別了這個HTTP請求的結束。通過計算cr
cr
兩個Annotation的時間戳之差,我們可以得到該HTTP請求從用戶端發起開始到接收服務端響應的總時間消耗。cs
-
-
:它用來對跟蹤資訊添加一些額外的補充說明,一般以鍵值對方式出現。比如:在記錄HTTP請求接收後執行具體業務邏輯時,此時并沒有預設的BinaryAnnotation
來辨別該事件狀态,但是有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
的總體依賴時間(cr - cs),也可以計算出trace-2
到trace-1
的網絡延遲(sr - cs),也可以計算出trace-2
應用用于處理用戶端請求的内部邏輯花費的時間延遲(ss - sr)。trace-2
- 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] | |
c48122fa096bffe8 | [trace-1,TraceApplication,trace] | |||
1ae2e9a317faa422 | [cs, cr] | |||
trace-2 | ||||
36194e4182985c4e | [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個标簽内容聯系起來:
-
的标簽有2個,分别是序号1和10,它們分别表示這次請求的開始和結束。它們對應了上表中ID為Span ID = T
的Span,該Span的内容在标簽10執行結束後,由e9a933ec50d180d6
将标簽1和10合并成一個Span發送給Zipkin Server。trace-1
-
的标簽有2個,分别是序号2和9,它們分别表示了Span ID = A
請求接收後,具體處理方法調用的開始和結束。該Span的内容在标簽9執行結束後,由trace-1
将标簽2和9合并成一個Span發送給Zipkin Server。trace-1
-
的标簽有4個,分别是序号3、4、7、8,該Span比較特殊,它的産生跨越了兩個執行個體,其中标簽3和8是由Span ID = B
生成的,而标簽4和7則是由trace-1
生成的,是以該标簽會拆分成兩個Span内容發送給Zipkin Server。trace-2
會在标簽8結束的時候将标簽3和8合并成一個Span發送給Zipkin Server,而trace-1
會在标簽7結束的時候将标簽4和7合并成一個Span發送給Zipkin Server。trace-2
-
的标簽有2個,分别是序号5和6,它們分别表示了Span ID = C
請求接收後,具體處理方法調用的開始和結束。該Span的内容在标簽6執行結束後,由trace-2
trace-2
是以,根據上面的分析,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請求的詳細資訊。
完整示例:
讀者可以根據喜好選擇下面的兩個倉庫中檢視
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版本做了更新。