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版本作了升级。