最近在使用Opentracing + Jaeger監控自己的雲端微服務程式時，遇到了難以排查的記憶體洩露問題。在進行效能測試時，記憶體中堆滿了JaegerSpan，JaegerSpanContext，以及其中的字串，看程式碼卻不知從何下手排查。
因此翻譯這篇來自Kiali開發工程師Juraci Paixao Kroehling的文章The Life of a Span，來了解一下Span的生命週期，希望能給問題排查帶來一些啟發。
以下為原文翻譯：
“Span”是分散式鏈路追蹤中的一個獨立單元，本篇文章將使用一個Jaeger應用的例子來展示span的生命週期，以及span是如何到達後臺收集分析系統的。
在OpenTracing，以及很多其它分散式鏈路追蹤的世界裡，“Span”描述的是一個儲存獨立工作單元資訊的資料結構。在大多數案例中，程式設計師只會關注如何例項化一個tracer，並且使用各種工具庫來記錄感興趣的Span資料，至於Span是如何到達後端收集服務如Jaeger的，大多數程式設計師並不清楚。
今天就讓我們來一探魔法背後的奧祕。
在後續的文字中，我們會聚焦於預設配置下所有元件的工作方式，這樣你就能清楚比對各個配置項之間的差異，並根據自己所作的配置知道自己的分散式鏈路追蹤在後臺是如何工作的了。
我們會使用Jaeger Java Client的一個應用示例來進行說明，其它語言的jaeger client庫也是基於類似原理進行工作。
應用配置
這篇部落格中使用的例子非常簡單，不會像通常大家做的那樣在GlobalTracer中註冊追蹤器。例子只會啟動一個Eclipse Vert.x，然後為receiver接收到的每個HTTP請求建立Span。例子中的程式碼可以在GitLab上找到，摘錄最關鍵的部分如下：
package com.example.demo;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import io.jaegertracing.Configuration;
import io.opentracing.Scope;
import io.opentracing.Tracer;
import io.vertx.core.AbstractVerticle;
import io.vertx.core.Vertx;
public class MainVerticle extends AbstractVerticle {
private static final Logger logger = LoggerFactory.getLogger(MainVerticle.class);
public static void main(String[] args) {
Vertx.vertx().deployVerticle(new MainVerticle());
}
@Override
public void start() throws Exception {
String serviceName = System.getenv("JAEGER_SERVICE_NAME");
if (null == serviceName || serviceName.isEmpty()) {
serviceName = "vertx-create-span";
}
System.setProperty("JAEGER_SERVICE_NAME", serviceName);
Tracer tracer = Configuration.fromEnv().getTracer();
vertx.createHttpServer().requestHandler(req -> {
try (Scope ignored = tracer.buildSpan("operation").startActive(true)) {
logger.debug("Request received");
req.response().putHeader("content-type", "text/plain").end("Hello from Vert.x!");
}
}).listen(8080);
logger.info("HTTP server started on port 8080");
}
}在啟動過程中，Jaeger Java Client會在背後建立一個RemoteReporter例項，從而啟動一個守護執行緒來不斷沖刷快取中儲存的Span（參見JAEGER_REPORTER_FLUSH_INTERVAL）。
這個Reporter會建立一個UdpSender例項，使用UDP和Thrift協議來向localhost執行的Jaeger Agent傳送抓取到的Span資訊。可以使用一個HttpSender來代替預設的UdpSender，這取決於追蹤器的配置。
建立Span
一旦工具庫，或者業務程式碼啟動了一個Span，Jaeger Java Client將會使用JaegerTracer.SpanBuilder來生成一個JaegerS的例項。這個例項會包含一個上下文物件（JaegerSpanContext）的引用。上下文中有一個TraceId以及一個SpanId，都會與Span樹的根節點（也叫Parent Span）保持一致。
Span上報
建立完Span之後，我們的工具庫程式碼就會做一些指定的處理，例如加一個指定的HTTP頭部，以及把回覆寫到Client中去。一旦這些處理完成，try-with-resource語句就會自動呼叫close()方法，而這個方法又會呼叫JaegerSpan#finish()。然後span就被JaegerTracer傳遞到RemoteReporter，此時我們的span長這樣：
JaegerSpan(
tracer=JaegerTracer(
version=Java-0.30.3-SNAPSHOT,
serviceName=vertx-create-span,
reporter=CompositeReporter(
reporters=...
),
sampler=ConstSampler(decision=true, tags={sampler.type=const, sampler.param=true}),
ipv4=-1062731773,
tags={hostname=caju.kroehling.de, jaeger.version=Java-0.30.3-SNAPSHOT, ip=192.168.0.3},
...
),
startTimeMicroseconds=1531757144093000,
startTimeNanoTicks=31909260878670,
computeDurationViaNanoTicks=true,
tags={sampler.type=const, sampler.param=true},
durationMicroseconds=9888,
operationName=operation,
references=[],
context=73abf3be4c32c2b8:73abf3be4c32c2b8:0:1,
logs=null,
finished=true
)RemoteReporter做的事很簡單，它會把Span新增到一個佇列中，然後就把控制權交還給呼叫者。因此在真實應用被追蹤的過程中，不會發生IO-blocking的處理，更不用說主執行緒會為span做什麼額外工作。
沖刷!
一旦span進入佇列中，後臺執行緒就會呼叫UdpSender#append(JaegerSpan)，把每個JaegerSpan轉換成Thrift span，然後把它們傳遞給agent。在轉換之後，我們的span長這樣：
Span(
traceIdLow:8335023534026965688,
traceIdHigh:0,
spanId:8335023534026965688,
parentSpanId:0,
operationName:operation,
references:[],
flags:1,
startTime:1531757144093000,
duration:9888,
tags:[
Tag(key:sampler.type, vType:STRING, vStr:const),
Tag(key:sampler.param, vType:BOOL, vBool:true)
],
logs:[]
)
這個Thrift形式的span會被新增到一個緩衝區中，同時sender會監視緩衝區大小，一旦達到UDP報文的最大值（大概65KB），或者達到預定的時間閾值，UdpSender就會加上一個Process物件一起沖刷span佇列，也就是追蹤器呼叫UdpSender#send(Process, List<JaegerSpan>)方法。這個函式是UdpSender向agent傳送Thrift報文的觸發器。如果你對Thrift報文感到好奇，它長這樣：
\ufffd\ufffd\u0001\temitBatch\u001c\u001c\u0018\u0011vertx-create-span\u0019<\u0018\u0008hostname\u0015\u0000\u0018\u0...Agent中的快閃
Jaeger Agent是緊挨著被追蹤程式的一個守護程式，它唯一的目的就是捕捉應用通過UDP提交的Span，並把Span通過一個保持連線的TChannel傳遞到資料採集器。
Agent接收到的一批Span被稱為“batch”，主要有兩個屬性：一個表示Jaeger Tracer所在程式後設資料的Process，以及一組Span。對於這一組Span來說，它們的後設資料都是一樣的，因此在一個batch中表示可能可以節省一些開銷。在我們的例子中，一個batch只有一個span，在被傳遞到collector前，它長這樣：
Batch({
Process:Process({
ServiceName:vertx-create-span
Tags:[
Tag({Key:hostname VType:STRING VStr:0xc4203621b0 VDouble:<nil> VBool:<nil> VLong:<nil> VBinary:[]})
Tag({Key:jaeger.version VType:STRING VStr:0xc420362260 VDouble:<nil> VBool:<nil> VLong:<nil> VBinary:[]})
Tag({Key:ip VType:STRING VStr:0xc420362280 VDouble:<nil> VBool:<nil> VLong:<nil> VBinary:[]})
]
})
Spans:[
Span({
TraceIdLow:8335023534026965688
TraceIdHigh:0
SpanId:8335023534026965688
ParentSpanId:0
OperationName:operation
References:[]
Flags:1
StartTime:1531757144093000
Duration:9888
Tags:[
Tag({Key:sampler.type VType:STRING VStr:0xc4203622a0 VDouble:<nil> VBool:<nil> VLong:<nil> VBinary:[]})
Tag({Key:sampler.param VType:BOOL VStr:<nil> VDouble:<nil> VBool:0xc42003ad5b VLong:<nil> VBinary:[]})
]
Logs:[]
})
]
})抵達收集器
Span結束了它在agent中的閃現，然後就會通過SpanHandler#SubmitBatches中的TChannel處理器（這個處理器只負責處理成Jaeger格式的batch，其它格式例如Zipkin會由其它處理器負責）傳遞到Jaeger收集器。
Batch被提交到收集器後，帶格式的負載長這樣：
[
{
"process": {
"serviceName": "vertx-create-span",
"tags": [
{
"key": "hostname",
"vType": "STRING",
"vStr": "caju.kroehling.de"
},
{
"key": "jaeger.version",
"vType": "STRING",
"vStr": "Java-0.30.3-SNAPSHOT"
},
{
"key": "ip",
"vType": "STRING",
"vStr": "192.168.0.3"
}
]
},
"spans": [
{
"traceIdLow": 8.335023534027e+18,
"traceIdHigh": 0,
"spanId": 8.335023534027e+18,
"parentSpanId": 0,
"operationName": "operation",
"flags": 1,
"startTime": 1.531757144093e+15,
"duration": 9888,
"tags": [
{
"key": "sampler.type",
"vType": "STRING",
"vStr": "const"
},
{
"key": "sampler.param",
"vType": "BOOL",
"vBool": true
}
]
}
]
}
]Span處理器會把它處理成Jaeger格式，每個Span帶上一個Process物件的copy，然後將處理後的佇列傳遞到SpanProcessor#ProcessSpans。我們的Span現在長這樣：
[
{
"trace_id": "AAAAAAAAAABzq\/O+TDLCuA==",
"span_id": "c6vzvkwywrg=",
"operation_name": "operation",
"references": null,
"flags": 1,
"start_time": "2018-07-16T16:05:44.093Z",
"duration": 9888000,
"tags": [
{
"key": "sampler.type",
"v_str": "const"
},
{
"key": "sampler.param",
"v_type": 1,
"v_bool": true
}
],
"logs": null,
"process": {
"service_name": "vertx-create-span",
"tags": [
{
"key": "hostname",
"v_str": "caju.kroehling.de"
},
{
"key": "jaeger.version",
"v_str": "Java-0.30.3-SNAPSHOT"
},
{
"key": "ip",
"v_str": "192.168.0.3"
}
]
}
}
]到了這一步，Span有可能會走一個預處理流程，也有可能直接被過濾掉。在通常情況下，Span會抵達SpanProcessor#saveSpan，如果我們的batch中有更多的span，就會看到每個span都會呼叫這個方法。這時一個Span Writer會被注入來進行處理，這個writer可能是Cassandra，ElastiSearch，Kafka或者記憶體writer，將Span寫入對應區域。
在這些集中儲存區中的Span長什麼樣，就留給讀者自己探尋。在Span轉換成Cassandra或Elasticsearch語義檔案之後，可能會包含大量的細節。
在此之後，我們就不再使用“Span”粒度進行闡述了。以後的場景中，我們觀察到的是一個由很多獨立span構成的成熟的追蹤鏈路。
UI和查詢
到了這個階段，我們的追蹤鏈路就躺在儲存區，等待著UI系統通過查詢語句來進行檢索。
在Jager UI中，我們可以基於service name（在我們的例子中就是vertx-create-span）等查詢術語來搜尋追蹤鏈路。在後臺，當我們選擇了service name，然後點選“Find Traces”，Jaeger查詢語句會被組織成如下形式：
{
"ServiceName": "vertx-create-span",
"OperationName": "",
"Tags": {
},
"StartTimeMin": "2018-07-16T17:06:38.426+02:00",
"StartTimeMax": "2018-07-16T18:06:38.426+02:00",
"DurationMin": 0,
"DurationMax": 0,
"NumTraces": 20
}查詢的APIHandler#Search方法會解析查詢術語，然後傳遞到各儲存器特定的Span Reader中。基於service name，我們的鏈路會被找到並新增到結果列表，在後臺這個列表是這樣的：
{
"traceID": "73abf3be4c32c2b8",
"spans": [
{
"traceID": "73abf3be4c32c2b8",
"spanID": "73abf3be4c32c2b8",
"flags": 1,
"operationName": "operation",
"references": [
],
"startTime": 1.531757144093e+15,
"duration": 9888,
"tags": [
{
"key": "sampler.type",
"type": "string",
"value": "const"
},
{
"key": "sampler.param",
"type": "bool",
"value": true
}
],
"logs": [
],
"processID": "p1",
"warnings": null
}
],
"processes": {
"p1": {
"serviceName": "vertx-create-span",
"tags": [
{
"key": "hostname",
"type": "string",
"value": "caju.kroehling.de"
},
{
"key": "ip",
"type": "string",
"value": "192.168.0.3"
},
{
"key": "jaeger.version",
"type": "string",
"value": "Java-0.30.3-SNAPSHOT"
}
]
}
},
"warnings": null
}所有的訊息在後臺被組織成特定格式，然後UI會收到這樣的資料：
{
"data": [
{
"traceID": "73abf3be4c32c2b8",
"spans": [
{
"traceID": "73abf3be4c32c2b8",
"spanID": "73abf3be4c32c2b8",
"flags": 1,
"operationName": "operation",
"references": [
],
"startTime": 1.531757144093e+15,
"duration": 9888,
"tags": [
{
"key": "sampler.type",
"type": "string",
"value": "const"
},
{
"key": "sampler.param",
"type": "bool",
"value": true
}
],
"logs": [
],
"processID": "p1",
"warnings": null
}
],
"processes": {
"p1": {
"serviceName": "vertx-create-span",
"tags": [
{
"key": "hostname",
"type": "string",
"value": "caju.kroehling.de"
},
{
"key": "ip",
"type": "string",
"value": "192.168.0.3"
},
{
"key": "jaeger.version",
"type": "string",
"value": "Java-0.30.3-SNAPSHOT"
}
]
}
},
"warnings": null
}
],
"total": 0,
"limit": 0,
"offset": 0,
"errors": null
}根據這個格式，Jaeger UI會迭代處理結果，並把它們的資訊漂亮地展示在螢幕上：
在大多數場景中，點選螢幕上展示的鏈路不會觸發UI的再次查詢。但如果我們開啟鏈路，並且點選了“Refresh”，UI就會執行一個ApiHandler#getTrace查詢。這個查詢根據給定的ID從儲存區中查詢所有相關span，然後回覆一個類似下面這樣的資料結構：
{
"spans": [
{
"trace_id": "AAAAAAAAAABzq\/O+TDLCuA==",
"span_id": "c6vzvkwywrg=",
"operation_name": "operation",
"references": null,
"flags": 1,
"start_time": "2018-07-16T16:05:44.093Z",
"duration": 9888000,
"tags": [
{
"key": "sampler.type",
"v_str": "const"
},
{
"key": "sampler.param",
"v_type": 1,
"v_bool": true
}
],
"logs": null,
"process": {
"service_name": "vertx-create-span",
"tags": [
{
"key": "hostname",
"v_str": "caju.kroehling.de"
},
{
"key": "ip",
"v_str": "192.168.0.3"
},
{
"key": "jaeger.version",
"v_str": "Java-0.30.3-SNAPSHOT"
}
]
}
}
],
"process_map": null
}由於我們只有一條鏈路，其中也只有一個span，因此UI獲得的payload與之前通過“search”操作獲得的一樣。不過資料展示方式不同：
Span來世
到此我們已經幾乎覆蓋了Span生命的所有階段，從它的起源直到最終它上報所追蹤應用的資訊。從此之後，Span還有可能在一些來世場景出現，例如成為Prometheus中的一個資料點，或者在Grafana dashboard中和其它Span整合在一起展示，等等等等。最終，管理員可能會決定清理一些歷史資料，然後我們的span就結束了整個生命迴圈，消失在歷史長河中。
問題後續
在這之後，一起開發的同事發現了我們Jaeger Span使用中的問題，主要原因是Span建立的語句沒有放到try with resource中去，導致記憶體中相關資源沒有被回收，產生的記憶體洩露。擷取程式碼如下：
原始碼：
@Around("@annotation(com.company.department.project.opentracing.Traced)")
public Object aroundTracedAdvice(ProceedingJoinPoint jp) throws Throwable {
Object res = null;
String className = jp.getTarget().getClass().getName();
String methodName = jp.getSignature().getName();
Span span = tracer.buildSpan(className + "." + methodName).withTag("class", className)
.withTag("method", methodName).start();
tracer.activateSpan(span);
try {
res = jp.proceed();
} catch (Throwable t) {
TracingUtils.onError(t, span);
throw t;
} finally {
span.finish();
}
return res;
}修改後的程式碼：注意其中scope放到了try with resource中去。
@Around("@annotation(com.company.department.project.opentracing.Traced)")
public Object aroundTracedAdvice(ProceedingJoinPoint jp) throws Throwable {
Object res = null;
String className = jp.getTarget().getClass().getName();
String methodName = jp.getSignature().getName();
Span span = tracer.buildSpan(className + "." + methodName).withTag("class", className)
.withTag("method", methodName).start();
try (Scope scope = tracer.activateSpan(span)) {
res = jp.proceed();
} catch (Throwable t) {
TracingUtils.onError(t, span);
throw t;
} finally {
span.finish();
}
return res;
}