关于jaeger:The-Life-of-a-Span

最近在应用 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;
}