浅谈Spring-cloud 之 sleuth 服务链路跟踪

Spring Cloud Sleuth 是 Spring Cloud 的一个组件，用于跟踪分布式系统的请求链路。Sleuth 的最终目标是通过跟踪服务的调用链路来生成分布式系统的请求跟踪图。

为什么需要服务链路跟踪

在一个分布式系统中，很多服务相互调用，一个请求对应着多个服务。系统运营商往往需要在出现问题时快速定位所需排查的服务，如果仅仅局限于单个服务而没有考虑分布式系统的服务调用链路，在排查问题时将会是很困难的。

很多系统运营商使用日志来查看某个服务的调用情况。但日志通常只记录了当前服务的信息，对于涉及到的其他服务信息无从知晓。因此，需要跟踪请求的整个服务调用链路才能有效地定位问题。

服务链路跟踪的实现原理

Sleuth 支持在分布式系统中提供唯一标识符。这些标识符随着请求从一个服务传递到另一个服务。Sleuth 使用这些标识符来构建分布式请求跟踪图。Sleuth 在分布式系统之间传播 trace-id，span-id 和 parent-span-id，通过 trace-id 将整个请求串联起来，通过 span-id 标记单个服务请求的唯一性，通过 parent-span-id 标记当前服务请求的父级请求的唯一性。

Sleuth 将调用过程中的信息写入 Zipkin，Zipkin 为分布式系统提供了一种寻找和排查相关请求的工具。Zipkin 可以查看请求链路，显示排队时间、服务延迟等数据，并显示各个节点之间的关系。此外，Sleuth 还提供了将跟踪信息输出到端点的能力，让你可以通过访问端点来查看应用程序中所有请求的跟踪信息。

如何使用 Sleuth 实现服务链路跟踪

引入 Sleuth 依赖

首先，在 pom.xml 中加入以下依赖：

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

修改日志配置

在 application.yml 中加入以下配置：

spring:
  sleuth:
    sampler:
      probability: 1
    traceId128: true
logging:
  level:
    org.springframework.cloud.sleuth: DEBUG

其中，sampler.probability 表示采样率，1 表示全部采样；traceId128 表示采用 128 位的 trace-id 编码；org.springframework.cloud.sleuth 表示 Sleuth 的详细日志级别。

使用示例

假设有 2 个微服务，一个服务调用另一个服务，下面用 Spring Boot 模拟一下。其中，server1 会发起对 server2 的调用。

server2

@RestController
@RequestMapping("/hello")
@Slf4j
public class HelloController {

    @GetMapping("/{name}")
    public String sayHello(@PathVariable String name) {
        log.info("server2 say hello to {}", name);
        return "Hello, " + name + "!";
    }
}

server1

@RestController
@Slf4j
public class DemoController {

    @Autowired
    private RestTemplate restTemplate;

    @GetMapping("/hello/{name}")
    public String hello(@PathVariable String name) {
        log.info("server1 says hello to {}", name);
        String result = restTemplate.getForObject("http://localhost:8082/hello/" + name, String.class);
        log.info("server1 received from server2: {}", result);
        return result;
    }
}

在 server1 中，需要注入一个 RestTemplate bean，在实际开发中，实现微服务间调用有多种方式，比如 Dubbo、Feign 等，这里只是简单举例使用了 RestTemplate。

添加 Sleuth 的依赖之后，再次运行应用程序，访问 server1 的 hello 接口，可以看到控制台输出的 Sleuth 的日志信息，如下：

2019-10-24 17:40:34.110  INFO [server1,0a50f4fd355f0762,0a50f4fd355f0762,false] 7309 --- [nio-8081-exec-1] DemoController: server1 says hello to John
2019-10-24 17:40:34.618  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] o.a.h.i.e.DefaultHttpRequestRetryHandler  : I/O exception (java.net.UnknownHostException) caught when processing request to {}->http://localhost:8082: nodename nor servname provided, or not known
2019-10-24 17:40:34.619  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] o.a.h.i.e.DefaultHttpRequestRetryHandler  : Retrying request to {}->http://localhost:8082
2019-10-24 17:40:34.855  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Received[GET /hello/John HttpHeaders(connection=[keep-alive], host=[localhost:8082], accept=[text/plain, application/json, application/*+json, */*])][]
2019-10-24 17:40:34.990  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [nio-8082-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-10-24 17:40:34.991  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [nio-8082-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-10-24 17:40:34.999  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [nio-8082-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 8 ms
2019-10-24 17:40:35.073  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [nio-8082-exec-1] HelloController: server2 say hello to John
2019-10-24 17:40:35.106  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [io-8082-exec-10] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Received[GET /hello/John HttpHeaders(connection=[keep-alive], host=[localhost:8082], accept=[text/plain, application/json, application/*+json, */*])][]
2019-10-24 17:40:35.108  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [io-8082-exec-10] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Created new span : + d0f85c84800b8c76
2019-10-24 17:40:35.108  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [io-8082-exec-10] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Adding new headers : + d0f85c84800b8c76
2019-10-24 17:40:35.119  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [io-8082-exec-10] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Received[GET /hello/John HttpHeaders(connection=[keep-alive], host=[localhost:8082], accept=[text/plain, application/json, application/*+json, */*])][d0f85c84800b8c76:d0f85c84800b8c76:0:1]
2019-10-24 17:40:35.119  INFO [server2,0a50f4fd355f0762,3f6fcf6ae0d3b521,false] 7309 --- [io-8082-exec-10] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Closed span : - d0f85c84800b8c76
2019-10-24 17:40:35.120  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Adding new headers : + d0f85c84800b8c76
2019-10-24 17:40:35.120  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] .t.TRACEIdFilterAndInterceptor$SleuthFiler: Close scope : - bean
2019-10-24 17:40:35.120  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] .t.TRACEIdFilterAndInterceptor$SleuthFiler: [Server1/0a50f4fd355f0762]  closed Span[d0f85c84800b8c76,d0f85c84800b8c76,false]
2019-10-24 17:40:35.121  INFO [server1,0a50f4fd355f0762,dc8cf3a2db731feb,false] 7309 --- [nio-8081-exec-1] DemoController: server1 received from server2: Hello, John!

Sleuth 的日志信息中，包含了服务的 trace-id，span-id 和 parent-span-id，可以清楚地看到 server1 调用了 server2，同时也可以看到 server2 对客户端发送了响应。这样，在出现问题时，我们只需要找到对应的 trace，就可以通过它追踪整个请求的调用情况，快速定位服务问题，提高排查问题的效率。

示例二

在服务中使用 Sleuth，不仅仅是为了排查问题，在实际开发中，还可以借助 Sleuth 的能力，对服务调用的性能情况进行监控。

我们在 server2 中添加一个耗时的接口，以实现监控：

@RestController
@RequestMapping("/slow")
@Slf4j
public class SlowController {

    @GetMapping("/{name}")
    public String doSlow(@PathVariable String name) {
        log.info("slow service starts to execute.");
        try {
            Thread.sleep(new Random().nextInt(1000));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        log.info("slow service ends to execute.");
        return "Hello, " + name + "!(" + LocalDateTime.now().format(DateTimeFormatter.ofPattern("HH:mm:ss")) + ")";
    }
}

在 server1 中，调用 server2 的 doSlow 接口：

@RestController
@Slf4j
public class DemoController {

    @Autowired
    private RestTemplate restTemplate;

    @GetMapping("/hello/{name}")
    public String hello(@PathVariable String name) {
        log.info("server1 says hello to {}", name);
        String result = restTemplate.getForObject("http://localhost:8082/slow/" + name, String.class);
        log.info("server1 received from server2: {}", result);
        return result;
    }
}

重启 server1 和 server2，分别访问 server1 的 hello 接口和 slow 接口，观察控制台输出，你会发现单独访问 server2 的 slow 接口时，耗时明显比访问 server1 的 hello 接口要长一些。

Sleuth 收集的信息有利于我们对性能进行监控，当某些服务响应时间超过预期时，我们可以通过 Sleuth 分析整个调用链路，找到具体的瓶颈位置，从而有针对性地进行优化。Sleuth 所收集的信息有助于我们发现并解决性能问题，提高分布式系统的可用性。

总结

本篇文章对 Spring Cloud Sleuth 进行了简单地介绍，并通过实际开发的示例以及效果演示，直观展示了 Sleuth 在服务链路跟踪以及性能监控方面的优点。在后续的系统开发中，可以结合 Zipkin 实现分布式系统的调用追踪，快速定位并解决问题，提高分布式系统的稳定性和可靠性。