微服务调用链日志追踪分析

一、技术原理

1.1 背景

微服务架构是一个分布式架构，它按业务划分服务单元，一个分布式系统往往有很多个服务单元。由于服务单元数量众多，业务的复杂性，如果出现了错误和异常，很难去定位。主要体现在，一个请求可能需要调用很多个服务，而内部服务的调用复杂性，决定了问题难以定位。所以微服务架构中，必须实现分布式链路追踪，去跟进一个请求到底有哪些服务参与，参与的顺序又是怎样的，从而达到每个请求的步骤清晰可见，出了问题，很快定位。

举个例子，在微服务系统中，一个来自用户的请求，请求先达到前端A（如前端界面），然后通过远程调用，达到系统的中间件B、C（如负载均衡、网关等），最后达到后端服务D、E，后端经过一系列的业务逻辑计算最后将数据返回给用户。对于这样一个请求，经历了这么多个服务，怎么样将它的请求过程的数据记录下来呢？这就需要用到服务链路追踪。

Google开源的 Dapper链路追踪组件，并在2010年发表了论文《Dapper, a Large-Scale Distributed Systems Tracing Infrastructure》，这篇文章是业内实现链路追踪的标杆和理论基础，具有非常大的参考价值。

中文翻译参考：
http://bigbully.github.io/Dapper-translation/

目前，链路追踪组件有Google的Dapper，Twitter 的Zipkin，以及阿里的Eagleeye （鹰眼）等，它们都是非常优秀的链路追踪开源组件。

1.2 名词术语

微服务链路追踪系统实现时，需设置一些关键节点记录信息，链路追踪相关名词如下：

Span：基本工作单元，发送一个远程调度任务 就会产生一个Span，Span是一个64位ID唯一标识的，Trace是用另一个64位ID唯一标识的，Span还有其他数据信息，比如摘要、时间戳事件、Span的ID、以及进度ID。

Trace：一系列Span组成的一个树状结构。请求一个微服务系统的API接口，这个API接口，需要调用多个微服务，调用每个微服务都会产生一个新的Span，所有由这个请求产生的Span组成了这个Trace。

Annotation：用来及时记录一个事件的，一些核心注解用来定义一个请求的开始和结束 。这些注解包括以下：

cs - Client Sent -客户端发送一个请求，这个注解描述了这个Span的开始

sr - Server Received -服务端获得请求并准备开始处理它，如果将其sr减去cs时间戳便可得到网络传输的时间。

ss - Server Sent （服务端发送响应）–该注解表明请求处理的完成(当请求返回客户端)，如果ss的时间戳减去sr时间戳，就可以得到服务器请求的时间。

cr - Client Received （客户端接收响应）-此时Span的结束，如果cr的时间戳减去cs时间戳便可以得到整个请求所消耗的时间。

1.3 调用链分析

一个服务调用过程如下图所示：

二、技术实现

调用方每一次向系统服务发起请求时，会生成这一次调用产生的相关调用链日志，生成一个全局的traceId，生成不同节点的span信息。其中当首个服务生成全局编码后，放入到header中，基于http传递给下级服务(其他模式类似)。下级服务可通过设置Filter过滤器（其他方案也可以），接收链路日志编码，并记录调用的日志信息。在将全局编码继续传递给下级服务。最终本次业务调用完成后，记录调用日志并清空本次调用链产生的全局编码。简易流程如下图所示：

2.1 单服务流程说明

1. 调用方请求服务A，进入服务A过滤器；
2. 服务A过滤器判断请求的header中是否携带了TraceId,ParentSpanId,有则使用携带的，没有就自动生成。
3. 过滤器前置部分记录初始请求的一些信息，如请求地址，参数，请求时间等；
4. 过滤器转发请求进入到Service方法;
5. 过滤器后置部分再次记录Service方法执行完成后的一些信息，如返回内容，结束时间；
6. 过滤器前后分别记录了信息，组合生成调用链路日志；
7. 请求完成后，清空本次产生的TraceId；

服务A调用链日志信息参考：

// trace日志
{
"message":"trace log",
"context":{
"trace_id":"e0d5c5ba-f497-4407-b8ca-f657a88452fc517513",
"request_uri":"/customize-trace-A/trace/jdk/async",
"request_method":"GET",
"refer_service_name":null,
"service_name":"customize-trace-A",
"refer_service_host":"127.0.0.1",
"request_time":1608896030.689531,
"response_time":1608896030.692276,
"time_used":3.479,
"service_addr":"192.168.45.42",
"service_port":8095,
"request_id":"9adfcf3c-d606-418f-abc7-6600bff6adf0533098"
},
"datetime":"2020-12-25 19:33:50.690014"
}
 
// span节点
{
"trace_id":"e0d5c5ba-f497-4407-b8ca-f657a88452fc517513",
"request_id":"9adfcf3c-d606-418f-abc7-6600bff6adf0533098",
"span":{
"span_id":"eb12eaf8-df3d-4dd2-923a-685360a4fd79588942",
"parent_id":null,
"duration":3426,
"annotations":[
{
"timestamp":1608896030686322,
"action":"sr"
},
{
"timestamp":1608896030689748,
"action":&#