调用链trace的设计分析

调用链trace系统可以帮助技术人员快速定位问题,而传统的监控一般只能反馈单个业务或者节点的故障问题,而不能掌握整个调用链路上的RPC服务质量。

关于调用链设计可以参考这篇博客《分布式会话跟踪系统架构设计与实践》,建议先读一下再来本博客(因为本博客没有任何贴图)。

下面谈一下这几个核心理念的设计。

基本概念

  • traceid:贯穿整个调用链传递,从而可以通过traceid一次性取出所有相关日志。
  • spanid:代表一次rpc调用(一次rpc调用的两头分别关联了1个client和1个server),spanid生成规则体现了调用的层级与时序。
    • 层级:0.1.1是0.1的子调用,0.1是0.1.1的父调用,而0.1.1自身完整的描述了自己的调用路径0 -> 0.1 -> 0.1.1,它是”完整”的。
    • 时序:0.1.1表示了0.1发起的第1次调用,0.1.2表示了0.1发起的第二次调用。
    • annotation:用户自定义的k-v信息,与traceid+spanid关联,后面会详细说明。

设计思路

认清rpc的两端

一次rpc分发起的客户端,以及处理请求的服务端。如果想完整的记录这一次rpc,那么应该从2方面入手:

  • 记录客户端从发出request到收到response的耗时T1。
  • 记录服务端从收到request到返回response的耗时T2。

有了这2个信息,就可以通过T1-T2大概计算出网络上的传输耗时,并且也知道rpc总耗时T1,以及服务端的处理耗时T2,基本覆盖全面了。

重要结论:T1耗时应该由客户端来记录日志,T2耗时应该由服务端来记录日志,即一次rpc至少有2条日志需要被输出并采集,才能完整的复原出这次rpc。

搞懂rpc的上下文

当然,如果上述日志只是client把T1耗时写到文件里,server把T2耗时写到文件里,那完全是没有意义的,因为缺少”上下文”。

为了事后复原rpc,至少应该记录一下T1耗时属于哪个traceid的哪次rpc吧,所以接下来就先说说”上下文”和traceid,spanid的关系。

我们知道spanid自身的结构完整的表达了rpc之间的层级和顺序关系(如果忘了回头看看),因此1个spanid在一个traceid下可以唯一的代表某次rpc调用。

而我们知道1次rpc调用会在client和server端分别打印一条日志记录相关的耗时信息,因此利用spanid将1次rpc的client和server输出的2条日志关联起来,从而描绘完整的一次rpc过程,是spanid的一个重要作用。

从专业术语来说,在client端生成的rpc日志和在server端生成的rpc日志被称为span,也就是1次rpc有2个span,它们通过一样的spanid关联在一起,而上下文信息都记录在span里,也就是client和server输出的2条日志里。(这么说已经够直白了吧!)

然而1次rpc的2个span记录的上下文信息除了spanid和traceid一样外,其他信息基本也没什么共同点了,毕竟要分别站在client和server两个角度去记录一些信息,必然是有所差异的,下面我们详细说一下哪些信息是必须要记录的。

span的建立时机

既然span代表了1次rpc两端的2行日志信息,那么client端的span应该伴随request的生成而生成,伴随response的收到而释放(写到日志中)。server端的span应该伴随request的收到而生成,伴随response的发出而释放(写到日志中)。

span里存什么上下文信息

无论对于client还是server来说,都要记录traceid表示所属的调用链,spanid表示本次rpc。

为了标明span属于client还是server侧,因此需要有一个flag标记一下span的来源是client or server。

对于client来说,要记录request的发出时间和response的收到时间,之间的耗时相减可以得到。

对于server来说,要记录request的收到时间和response的发出时间,之间的耗时相减可以得到。

为了更具体的描述1次rpc,应该在client的span里记录rpc发起方的服务名称(比如:交易服务),在server的span里记录rpc接收方的服务名称(比如:反作弊服务),这样rpc就描绘的更加具体了:交易服务 -> 反作弊服务的1次rpc调用。

类似的,记录其他信息也是很重要的,比如:记录本机(client和server各自获取)的IP,request请求的地址(比如URL)是什么(也就是rpc调用的接口是什么),甚至client和server创建span时的函数名,代码行号是什么,等等。

日志长什么样

根据上述理论,只保留最基础的span信息,打印的日志会是这样的:

traceid spanid app start_time end_time flag
3100 0 交易服务 2017-06-01 10:00:00:0000 2017-06-01 10:00:00:0070 server
3100 0.1 交易服务 2017-06-01 10:00:00:0005 2017-06-01 10:00:00:0045 client
3100 0.1 反作弊服务 2017-06-01 10:00:00:0015 2017-06-01 10:00:00:0040 server
3100 0.1.1 反作弊服务 2017-06-01 10:00:00:0020 2017-06-01 10:00:00:0035 client
3100 0.1.1 用户服务 2017-06-01 10:00:00:0025 2017-06-01 10:00:00:0030 server
 3100 0.2 交易服务 2017-06-01 10:00:00:0050 2017-06-01 10:00:00:65  client
3100 0.2 库存服务 2017-06-01 10:00:00:0055 2017-06-01 10:00:00:60 server

上表描述一个场景:”交易服务”收到”用户”的请求,先调用了”反作弊服务”,”反作弊服务”间接调用了”用户服务”,当”反作弊服务”收到”用户服务”的应答后,”反作弊服务”会返回应答到”交易服务”,”交易服务”收到”反作弊服务”应答后,会调用”库存服务”,收到应答后将在2017-06-01 10:00:00:0070将最终应答发给”用户”。

这里面一共涉及了0,0.1,0.11,0.2共4个rpc,其中0只有server端(因为客户端是外部用户的请求,普通用户是不会替我们打印client端span日志的),而其他3个rpc均有client和server两端的日志。

我特意将所有的span按照spanid顺序排列,相同spanid会靠在一起凑成一对,代表1次rpc。由于spanid的构造特性,所以从上到下表现了调用的时序和层级关系,和我描述的调用流程一致。

从上至下查看它们的start_time,有明显的递增趋势,这是因为按spanid的构造特性排序,越靠下的调用时间越晚,但是end_time没有规律,因为相同层级的连续rpc的end_time从上向下递增(例如0.1和0.2的关系),而父层级的end_time一定是子层级完成后才记录的(例如0.1和0.1.1的关系)。

正因为start_time是递增的,所以按照spanid特性排序后,可以利用start_time做”时序图”。

关于annotation

从上面的日志可以看出,只保留rpc的调用耗时和时间轴,顶多能看出哪里慢,但是为什么慢或者遇到了什么报错,就无从记录了。

所以在做调用链trace的时候,应该允许用户保存更多关于rpc调用的业务详情信息,这就是annotation。

annotation是描述1次rpc的订制业务信息的,比如:错误码,请求体,等等。因此,annotation只要和traceid+spanid关联,就可以明确的表达某个rpc的附加信息了。

1次rpc可以关联很多annotation,通常将每一条annotation作为单独一行日志输出。我们回到上述表格,将annotation信息加进入:

traceid spanid app start_time end_time flag key value
3100 0 交易服务 2017-06-01 10:00:00:0000 2017-06-01 10:00:00:0070 server
3100 0.1 交易服务 2017-06-01 10:00:00:0005 2017-06-01 10:00:00:0045 client
3100 0.1 反作弊服务 2017-06-01 10:00:00:0015 2017-06-01 10:00:00:0040 server
3100 0.1.1 反作弊服务 2017-06-01 10:00:00:0020 2017-06-01 10:00:00:0035 client
3100 0.1.1 反作弊服务 annotation(client)  response {‘errno:’ 0, ‘msg’: ‘success’, ‘data’: {}}
3100 0.1.1 用户服务 2017-06-01 10:00:00:0025 2017-06-01 10:00:00:0030 server
3100 0.1.1 用户服务   annotation(server) userinfo {‘uid’: 10, ‘username’: ‘owen’}
 3100 0.2 交易服务 2017-06-01 10:00:00:0050 2017-06-01 10:00:00:65  client
3100 0.2 库存服务 2017-06-01 10:00:00:0055 2017-06-01 10:00:00:60 server

上述表格中加粗的部分是annotation,它们通过traceid+spanid关联到1个rpc调用,作为附加信息存在。每一行annotation有一个key标识数据的意义,value则存储任意业务自定义数据。annotation可以在client端生成,也可以在server端生成,这个没有什么强制要求。

关于上下文透传

为了维护整个调用链,需要在所有的请求中透传traceid和spanid。其中traceid用于找出所有日志,而spanid则维护rpc的层级和时序。

注意,调用链trace日志记录是所有的rpc调用,相当于调用树中一条一条的边而不是点,只是这个边记录了两端的信息而已。

当client发起rpc调用时,应该生成该rpc的spanid并创建对应的span,spanid随着rpc并透传给server,当server收到request后会根据透传spanid创建一个span对应本次rpc。比如:前一个rpc的server端spanid=0,它转而发起了1次rpc,那么新的rpc的spanid=0.1,新rpc的server端收到spanid=0.1的请求后,如果继续向其他server发起rpc,那么新rpc的spanid=0.1.1,也就是说spanid是标识rpc的,不是标识服务节点的,它是”边”不是”顶点”。

总结:

  • spanid代表一条rpc,rpc分client和server共2个参与者,它们各自生成一条span日志,代表了spanid这条边的2个端点。
  • 如果一个server被调用时,又作为client发起了其他rpc,那么新的rpc应该创建request并开启新的client span,对应的spanid应该在之前的spanid基础上继续扩展。

关于UI展示

这些日志采集后应该存储起来,可以将traceid+spanid作为key,存储到es或者hbase里,前者支持检索,后者支持范围scan,都可以根据traceid快速的拿到关联的所有日志记录。

有了1个traceid关联的所有span后,首先要像上面的表格一样排序,也就是将spanid按.分割,然后从左边开始比较,哪个数字(整形)小就排在前面,哪个spanid短就排在前面,排序后就可以体现出调用时序从先到后的关系了。

接下来,应该扫描一次表格,对相邻的相同spanid进行日志聚合,将client端,server端以及annotation信息全部聚合到同一个spanid下,因为一个spanid代表一个rpc,也就是每个rpc的信息都整合到了一起。

最后,就是在UI上画出时序图,这一点可以利用client的start_time去画,因为start_time从上向下是递增的。可以在UI图的左侧体现出每一行rpc的层级,根据spanid按.分割后的片段数量即可获知。


本文其他参考:《基于zipkin的Thrift服务RPC调用链追踪》

 

 

如果文章帮助您解决了工作难题,您可以帮我点击屏幕上的任意广告,或者赞助少量费用来支持我的持续创作,谢谢~