在本节内容之前, 我们已经对如何引入 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 IDSpan 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 IDSpan IDTags(对应 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);
- }
- Github:https://github.com/dyc87112/SpringCloud-Learning/
- Gitee:https://gitee.com/didispace/SpringCloud-Learning/
来源: https://segmentfault.com/a/1190000013343984