Spring Cloud 学习笔记 - No.8 分布式服务跟踪

请先阅读之前的内容：

• Spring Cloud 学习笔记 - No.1 服务注册发现
• Spring Cloud 学习笔记 - No.2 服务消费 Ribbon & Feign
• Spring Cloud 学习笔记 - No.3 分布式配置 Config
• Spring Cloud 学习笔记 - No.4 断路器 Hystrix
• Spring Cloud 学习笔记 - No.5 服务网关 Zuul
• Spring Cloud 学习笔记 - No.6 通过 Swagger2 构建 API 文档
• Spring Cloud 学习笔记 - No.7 消息驱动 Stream

在我们之前的例子中，服务 eureka-consumer 中的 /consumer 接口实际上是通过 Rest 调用服务 eureka-client 中的 /add 接口来实现具体的计算逻辑。

生产环境中，通常一个由客户端发起的请求在后端系统中会经过多个不同的微服务调用来协同产生最后的请求结果，即形成一条复杂的分布式服务调用链路，在每条链路中任何一个依赖服务出现延迟过高或错误的时候都有可能引起请求最后的失败。
这时候对于每个请求分布式服务调用链路的跟踪就变得越来越重要，通过实现对请求调用的跟踪可以帮助我们快速的发现错误根源以及监控分析每条请求链路上的性能瓶颈。

针对上面所述的分布式服务跟踪问题，Spring Cloud Sleuth 提供了一套完整的解决方案。
网址：https://cloud.spring.io/spring-cloud-sleuth/

Spring Cloud Sleuth implements a distributed tracing solution for Spring Cloud, borrowing heavily from Dapper, Zipkin and HTrace. For most users Sleuth should be invisible, and all your interactions with external systems should be instrumented automatically. You can capture data simply in logs, or by sending it to a remote collector service.

首先我们分别在服务 eureka-consumer 中的 /consumer 接口和服务 eureka-client 中的 /add 接口中添加日志：

@ApiOperation(value = "提供 1 + 2 的加法结果", notes = "")
@GetMapping("/consumer")
public String consumer() {
    logger.info("{} REST API provided by {}", "consumer", "eureka-consumer");
    return consumerService.consumer();
}

@GetMapping("/add")
public Integer add(@RequestParam Integer operand1, @RequestParam Integer operand2) throws InterruptedException {

    logger.info("{} REST API provided by {}", "add", "eureka-client");

    return operand1 + operand2;
}

重启服务，调用 http://127.0.0.1:3001/consumer（调用两次），
我们从 eureka-consumer 的日志输出中可以看到：

INFO 56477 --- [nio-3001-exec-4] c.example.controller.ConsumerController  : consumer REST API provided by eureka-consumer
INFO 56477 --- [nio-3001-exec-4] c.example.controller.ConsumerController  : consumer REST API provided by eureka-consumer

我们从 eureka-client 的日志输出中可以看到：

INFO 56356 --- [nio-2002-exec-3] c.e.controller.CalculatorController      : add REST API provided by eureka-client
INFO 56356 --- [nio-2002-exec-3] c.e.controller.CalculatorController      : add REST API provided by eureka-client

但是这样存在一个问题：这两条日志直接并不能看出关联关系。例如，我们发送了好多次请求，那么在日志中就会出现好多条 consumer REST API provided by eureka-consumer 和好多条 add REST API provided by eureka-client。
那么第几条 consumer REST API provided by eureka-consumer 和 第几条 add REST API provided by eureka-client 处于同一个分布式服务调用链路？我们无法得知。

实现跟踪

我们在 eureka-consumer 和 eureka-client 分别添加如下依赖：

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

添加 spring-cloud-starter-sleuth 依赖之后， 它会自动的为当前应用构建起各通信通道的跟踪机制，比如：

• 通过诸如 RabbitMQ、Kafka 等消息中间件传递的请求
• 通过 Zuul 服务网关传递的请求
• 通过 RestTemplate 发起的请求

重启服务，调用 http://127.0.0.1:3001/consumer （调用两次），
我们从 eureka-consumer 的日志输出中可以看到：

INFO [eureka-consumer,7d46e2f108b162a3,7d46e2f108b162a3,false] 60307 --- [nio-3001-exec-5] c.example.controller.ConsumerController  : consumer REST API provided by eureka-consumer
INFO [eureka-consumer,b1ec47bd025f3650,b1ec47bd025f3650,false] 60307 --- [nio-3001-exec-7] c.example.controller.ConsumerController  : consumer REST API provided by eureka-consumer

我们从 eureka-client 的日志输出中可以看到：

INFO [eureka-client,7d46e2f108b162a3,39b07f1c5d3f1a2a,false] 59975 --- [nio-2001-exec-9] c.e.controller.CalculatorController      : add REST API provided by eureka-client
INFO [eureka-client,b1ec47bd025f3650,52375bb6fdb08a40,false] 60113 --- [nio-2002-exec-6] c.e.controller.CalculatorController      : add REST API provided by eureka-client

我们可以看到多了一些形如 [eureka-consumer,7d46e2f108b162a3,7d46e2f108b162a3,false] 的日志信息，而这些元素正是实现分布式服务跟踪的重要组成部分，它们每个值的含义如下：

• 第一个值：eureka-consumer，它记录了应用的名称。
• 第二个值：7d46e2f108b162a3，Spring Cloud Sleuth 生成的一个ID，称为 Trace ID，它用来标识一条请求链路。一条分布式服务调用链路中包含一个 Trace ID，多个 Span ID。
• 第三个值：7d46e2f108b162a3，Spring Cloud Sleuth 生成的另外一个ID，称为 Span ID，它表示一个基本的工作单元，比如：发送一个 HTTP 请求。
• 第四个值：false，表示是否要将该信息输出到 Zipkin 等服务中来收集和展示。

从上面的日志中，我们可以看出，第一次 http://127.0.0.1:3001/consumer 调用的 Trace ID 为 7d46e2f108b162a3，它对应了两个 Span ID，即两次 HTTP 请求：

• 请求到 eureka-consumer，Span ID 为 7d46e2f108b162a3
• 请求到 eureka-client，Span ID 为 39b07f1c5d3f1a2a

实现原理

• 当请求发送到分布式系统的入口端点时（例如上面的 /consumer），Spring Cloud Sleuth 为该请求创建一个唯一的跟踪标识，同时在分布式系统内部流转的时候，框架始终保持传递该唯一标识，直到返回给请求方为止，这个唯一标识就是前文中提到的 Trace ID（例如上面的 7d46e2f108b162a3)。通过 Trace ID 的记录，我们就能将所有请求过程日志关联起来。
• 为了统计各处理单元的时间延迟，当请求达到各个服务组件时，或是处理逻辑到达某个状态时，也通过一个唯一标识来标记它的开始、具体过程以及结束，该标识就是我们前文中提到的 Span ID（例如上面的 39b07f1c5d3f1a2a)，对于每个 Span 来说，它必须有开始和结束两个节点，通过记录开始 Span 和结束 Span 的时间戳，就能统计出该 Span 的时间延迟，除了时间戳记录之外，它还可以包含一些其他元数据，比如：事件名称、请求信息等。

整合 ELK

在上面的例子中，日志文件都离散的存储在各个服务实例的文件系统之上，仅仅通过查看日志文件来分析分布式服务调用链路依然是一件相当麻烦的差事，所以我们还需要一些工具来帮助我们集中的收集、存储和搜索这些跟踪信息。

ELK 平台主要有由 ElasticSearch、Logstash 和 Kiabana 三个开源免费工具组成，具体参见 ELK 三件套的一些实践。

Spring Cloud Sleuth 在与 ELK 平台整合使用时，实际上我们只要实现与负责日志收集的 Logstash 完成数据对接即可，所以我们需要为 Logstash 准备 JSON 格式的日志输出。
由于 Spring Boot 应用默认使用了 Logback 来记录日志，而 Logstash 自身也有对 Logback 日志工具的支持工具，所以我们可以直接通过在 Logback 的配置中增加对 Logstash 的 Appender，就能非常方便的将日志转换成以 JSON 的格式存储和输出了。

我们在 eureka-consumer 和 eureka-client 分别添加如下依赖：

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>4.9</version>
</dependency>

我们在 eureka-consumer 和 eureka-client 分别添加配置文件 /resources/logback-spring.xml。可以看出，我们为日志定义两个 Appender：

• 一个是控制台 ConsoleAppender
• 一个是地址为 127.0.0.1:9250 的 LogstashTcpSocketAppender

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <springProperty scope="context" name="springAppName" source="spring.application.name"/>

    <!-- 控制台的日志输出样式 -->
    <property name="CONSOLE_LOG_PATTERN"
              value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr([${springAppName:-},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]){yellow} %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>

    <!-- 控制台Appender -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <!-- 将日志内容直接通过 Tcp Socket 输出到 Logstash 服务端 -->
    <appender name="logstash" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
        <destination>127.0.0.1:9250</destination>
        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <providers>
                <timestamp>
                    <timeZone>UTC</timeZone>
                </timestamp>
                <pattern>
                    <pattern>
                        {
                        "severity": "%level",
                        "service": "${springAppName:-}",
                        "trace": "%X{X-B3-TraceId:-}",
                        "span": "%X{X-B3-SpanId:-}",
                        "exportable": "%X{X-Span-Export:-}",
                        "pid": "${PID:-}",
                        "thread": "%thread",
                        "class": "%logger{40}",
                        "rest": "%message"
                        }
                    </pattern>
                </pattern>
            </providers>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="console"/>
        <appender-ref ref="logstash"/>
    </root>
</configuration>

确保 ELK 三件套已正常启动并部署，参见 ELK 三件套的一些实践。
重启 eureka-consumer（端口 3001，3002） 和 eureka-client（端口 2001，2002），调用 http://127.0.0.1:3001/consumer，http://127.0.0.1:3002/consumer（调用多次）。

随后我们进入到 Kibana 管理页面 http://localhost:5601/。
首先创建一个索引模式 Index Patterns，名称为 testing-log：

创建一个索引模式 Index Patterns
然后我们可以在 Discover 页面做一个查询，例如我们想知道 Trace Id 为 22829366859badc0 的日志，可以通过如下方式：
Trace Id 为 22829366859badc0 的日志

整合 Zipkin

在 ELK 平台中的数据分析维度缺少对请求链路中各阶段时间延迟的关注，对于这样的问题，我们就可以引入 Zipkin 来解决。

Zipkin 简介

https://zipkin.io/

Zipkin is a distributed tracing system. It helps gather timing data needed to troubleshoot latency problems in microservice architectures. It manages both the collection and lookup of this data. Zipkin’s design is based on the Google Dapper paper.
Applications are instrumented to report timing data to Zipkin.
The Zipkin UI also presents a Dependency diagram showing how many traced requests went through each application.

图片引用自：http://blog.didispace.com/spring-cloud-starter-dalston-8-4/

Zipkin 的基础架构

• Collector：收集器组件，处理从外部系统发送过来的跟踪信息，将这些信息转换为 Zipkin 内部处理的 Span 格式，以支持后续的存储、分析、展示等功能。
• Storage：存储组件，处理收集器接收到的跟踪信息，默认会将这些信息存储在内存中，我们也可以修改此存储策略，通过使用其他存储组件将跟踪信息存储到数据库中。
• RESTful API：API 组件，它主要用来提供外部访问接口。比如给客户端展示跟踪信息，或是外接系统访问以实现监控等。
• Web UI：UI组件，基于API组件实现的上层应用。通过 UI 组件用户可以方便而有直观地查询和分析跟踪信息。

Zipkin 通过 HTTP 收集数据

首先创建一个 Zipkin 服务器，这是一个 Spring Boot 应用，命名为 zipkin-server，添加如下依赖：

<dependencies>
    <dependency>
        <groupId>io.zipkin.java</groupId>
        <artifactId>zipkin-server</artifactId>
    </dependency>
    <dependency>
        <groupId>io.zipkin.java</groupId>
        <artifactId>zipkin-autoconfigure-ui</artifactId>
    </dependency>
</dependencies>

注意：由于 Zipkin 目前不兼容 Spring Boot 2.0，请使用 1.5 版本的 Spring Boot：

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>1.5.10.RELEASE</version>
    <relativePath/> <!-- lookup parent from repository -->
</parent>

随后使用 @EnableZipkinServer 注解来启动 Zipkin Server：

@SpringBootApplication
@EnableZipkinServer
public class ZipkinServerApplication {

    public static void main(String[] args) {
        SpringApplication.run(ZipkinServerApplication.class, args);
    }
}

在 application.properties 中设置端口：

spring.application.name=zipkin-server
server.port=4321

最后通过 mvn spring-boot:run 启动 并访问 http://127.0.0.1:4321/ 来访问 Zipkin Web UI：

Zipkin Web UI

现在我们要为应用 eureka-consumer 和 eureka-client 引入和配置 Zipkin 服务。
我们在 eureka-consumer 和 eureka-client 分别添加如下依赖：

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-sleuth-zipkin</artifactId>
</dependency>

我们在 eureka-consumer 和 eureka-client 的 application.properties 中增加 Zipkin Server 的配置信息：

spring.zipkin.baseUrl=http://localhost:4321

我们在 eureka-consumer 和 eureka-client 的启动程序中添加：（具体原因下面《抽样收集》会补充说明）

@Bean
public Sampler defaultSampler() {
    return Sampler.ALWAYS_SAMPLE;
}

重启 eureka-consumer（端口 3001，3002） 和 eureka-client（端口 2001，2002），调用 http://127.0.0.1:3001/consumer，http://127.0.0.1:3002/consumer（调用多次）。

随后我们进入到 Zipkin Web UI http://127.0.0.1:4321/：

Zipkin Web UI

Zipkin 通过 消息中间件 收集数据

Spring Cloud Sleuth 在整合 Zipkin 时，不仅实现了以 HTTP 的方式收集跟踪信息，还实现了通过消息中间件来对跟踪信息进行异步收集的封装。通过结合 Spring Cloud Stream，我们可以非常轻松的让应用客户端将跟踪信息输出到消息中间件上，同时 Zipkin 服务端从消息中间件上异步地消费这些跟踪信息。

具体参见 http://blog.didispace.com/spring-cloud-starter-dalston-8-4/

Zipkin 数据模型

• Span：它代表了一个基础的工作单元。每一个不同的工作单元都通过一个64位的ID来唯一标识，称为 Span ID。另外，在工作单元中还存储了一个用来串联其他工作单元的ID，它也通过一个64位的ID来唯一标识，称为 Trace ID。
• Trace：它是由一系列具有相同 Trace ID 的 Span 串联形成的一个树状结构。
• 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：它用来对跟踪信息添加一些额外的补充说明，一般以键值对方式出现。

抽样收集

我们收集的跟踪信息越多就可以更好的反映出系统的实际运行情况，并给出更精准的预警和分析，但是在高并发的分布式系统运行时，大量的请求调用会产生海量的跟踪日志信息，如果我们收集过多的跟踪信息将会对我们整个分布式系统的性能造成一定的影响，同时保存大量的日志信息也需要不少的存储开销。
所以，在 Sleuth 中采用了抽样收集的方式来为跟踪信息打上收集标记，也就是我们之前在日志信息中看到的第四个 boolean 类型的值，它代表了该信息是否要被后续的跟踪信息收集器获取和存储。

Sampling is an up-front decision, meaning that the decision to report data is made at the first operation in a trace and that decision is propagated downstream.

在 Sleuth 中的抽样收集策略是通过 Sampler 抽象类实现的，它的定义如下：

public abstract class Sampler {
    public static final Sampler ALWAYS_SAMPLE = new Sampler() {
        public boolean isSampled(long traceId) {
            return true;
        }

        public String toString() {
            return "AlwaysSample";
        }
    };
    public static final Sampler NEVER_SAMPLE = new Sampler() {
        public boolean isSampled(long traceId) {
            return false;
        }

        public String toString() {
            return "NeverSample";
        }
    };

    public Sampler() {
    }

    public abstract boolean isSampled(long var1);

    public static Sampler create(float rate) {
        return CountingSampler.create(rate);
    }
}

通过覆盖 isSampled 方法，Spring Cloud Sleuth 会在产生跟踪信息的时候调用它来为跟踪信息生成是否要被收集的标志。需要注意的是，即使 isSampled 返回了 false，它仅代表该跟踪信息不被输出到后续对接的远程分析系统（比如：Zipkin），对于请求的跟踪活动依然会进行，所以我们在日志中还是能看到收集标识为 false的记录。
Sleuth 会使用 PercentageBasedSampler 实现的抽样策略，以请求百分比的方式配置和收集跟踪信息，我们可以通过在 application.properties 中配置下面的参数对其百分比值进行设置，它的默认值为 0.1，代表收集 10% 的请求跟踪信息：

spring.sleuth.sampler.percentage=0.1

也可以通过创建 AlwaysSampler 的 Bean（它实现的 isSampled 方法始终返回 true）：

@Bean
public Sampler defaultSampler() {
    return Sampler.ALWAYS_SAMPLE;
}

---

引用：
程序猿DD Spring Cloud基础教程
Spring Cloud构建微服务架构：分布式服务跟踪（入门）
Spring Cloud构建微服务架构：分布式服务跟踪（跟踪原理）
Spring Cloud构建微服务架构：分布式服务跟踪（整合logstash）
Spring Cloud构建微服务架构：分布式服务跟踪（整合zipkin）
Spring Cloud构建微服务架构：分布式服务跟踪（收集原理）
Spring Cloud构建微服务架构：分布式服务跟踪（抽样收集）
Spring Cloud Dalston中文文档