乐趣区

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

作者：

jiezi

在

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

评论

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注

这个站点使用 Akismet 来减少垃圾评论。了解你的评论数据如何被处理。

更多文章