做网站平台公司,网站建设硬件环境,网站建设完整教程视频教程,it培训机构包就业在本节内容之前#xff0c;我们已经对如何引入Sleuth跟踪信息和搭建Zipkin服务端分析跟踪延迟的过程做了详细的介绍#xff0c;相信大家对于Sleuth和Zipkin已经有了一定的感性认识。接下来#xff0c;我们介绍一下关于Zipkin收集跟踪信息的过程细节#xff0c;以帮助我们更…在本节内容之前我们已经对如何引入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来标识一个请求的开始和结束 csClient Send该Annotation用来记录客户端发起了一个请求同时它也标识了这个HTTP请求的开始。srServer Received该Annotation用来记录服务端接收到了请求并准备开始处理它。通过计算sr与cs两个Annotation的时间戳之差我们可以得到当前HTTP请求的网络延迟。ssServer Send该Annotation用来记录服务端处理完请求后准备发送请求响应信息。通过计算ss与sr两个Annotation的时间戳之差我们可以得到当前服务端处理请求的时间消耗。crClient Received该Annotation用来记录客户端接收到服务端的回复同时它也标识了这个HTTP请求的结束。通过计算cr与cs两个Annotation的时间戳之差我们可以得到该HTTP请求从客户端发起开始到接收服务端响应的总时间消耗。BinaryAnnotation它用来对跟踪信息添加一些额外的补充说明一般以键值对方式出现。比如在记录HTTP请求接收后执行具体业务逻辑时此时并没有默认的Annotation来标识该事件状态但是有BinaryAnnotation信息对其进行补充。
收集机制
在理解了Zipkin的各个基本概念之后下面我们结合前面章节中实现的例子来详细介绍和理解Spring Cloud Sleuth是如何对请求调用链路完成跟踪信息的生产、输出和后续处理的。
首先我们来看看Sleuth在请求调用时是怎么样来记录和生成跟踪信息的。下图展示了我们在本章节中实现示例的运行全过程客户端发送了一个HTTP请求到trace-1trace-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的配置对其进行修改。
MessageEndpointConditional(NotSleuthStreamClient.class)public class ZipkinMessageListener { final Collector collector; ServiceActivator(inputChannel SleuthSink.INPUT) public void sink(Spans input) { Listzipkin.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的父子关系最后整理出的结果
HostSpan IDParent Span IDAnnotationBinary Annotationtrace-1e9a933ec50d180d6null[sr, ss]trace-1c48122fa096bffe8e9a933ec50d180d6[trace-1,TraceApplication,trace]trace-11ae2e9a317faa422c48122fa096bffe8[cs, cr]trace-21ae2e9a317faa422c48122fa096bffe8[sr, ss]trace-236194e4182985c4e1ae2e9a317faa422[trace-2,TraceApplication,trace]
上表中的Host代表了该Span是从哪个应用发送过来的Span ID是当前Span的唯一标识Parent Span ID代表了上一执行单元的Span IDAnnotation代表了该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个分别是序号3、4、7、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 IDB的标签由于它们来自于同一个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请求的详细信息。 完整示例
读者可以根据喜好选择下面的两个仓库中查看trace-1和trace-2两个项目
Githubhttps://github.com/dyc87112/SpringCloud-Learning/Giteehttps://gitee.com/didispace/SpringCloud-Learning/
如果您对这些感兴趣欢迎star、follow、收藏、转发给予支持
本文内容部分节选自我的《Spring Cloud微服务实战》但对依赖的Spring Boot和Spring Cloud版本做了升级。
