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

请先阅读之前的内容：

在我们之前的例子中，服务 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中文文档

最后编辑于：2018.07.24 15:26:38

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 202,529评论 5赞 475
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 85,015评论 2赞 379
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 149,409评论 0赞 335
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 54,385评论 1赞 273
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 63,387评论 5赞 364
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 48,466评论 1赞 281
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 37,880评论 3赞 395
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 36,528评论 0赞 256
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 40,727评论 1赞 295
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 35,528评论 2赞 319
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 37,602评论 1赞 329
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 33,302评论 4赞 318
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 38,873评论 3赞 306
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 29,890评论 0赞 19
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 31,132评论 1赞 259
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 42,777评论 2赞 349
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 42,310评论 2赞 342