微服务的全链路日志分布式链路追踪系统

微服务架构去中心化，让每个业务可以轻松独立出一个高自治性的服务。如今我所参与研发项目，划分出了几十个微服务，由不同的团队负责，这些服务之间相互调用。微服务的好处不用多说，但也会因此引发一些问题，例如：

测试同事反馈我负责服务的接口报错了，而往往错误的程序不在我的代码里，而是所依赖的下游服务出错了，然后得去联系负责对应服务的团队。当一个接口报错了，如何能马上定位到哪个服务出问题呢？
领导提出要提高某个接口的响应速度，可这个接口同样调用了好几个下游服务接口，该如何定位性能瓶颈呢？

诸如此类的有很多，当微服务越来越多，就越能发现全链路日志的重要性。目前比较常见的解决方案是 Spring Cloud Sleuth，本文讲解一下它的使用方法。还会分析一下它实现的原理，然后探讨一下基于该原理自定义实现的方案。
1. Sleuth 1.1. 概念
Spring Cloud Sleuth 可以用来追踪微服务请求中的整个请求，通过它可以记录各个请求之间的耗时、异常等情况。Sleuth 记录的这些信息，需要有系统来收集、存储和查询，市场上有很多工具配合，如：Zipkin、Skywalking、pinpoint等。拿最简单的 Zipkin来说，Spring Cloud Sleuth收集到的一些跟踪信息可以发送给Zipkin，Zipkin提供了图形化界面方便查看服务之间的调用关系和调用耗时等情况。
我们先来看几个Spring Cloud Sleuth里面的基本概念。

service: 服务名，它默认就取spring.application.name。
span : 直接翻译就是跨度，比如service1调用service2，这一个来回可以算一个span。每个span都由一个唯一的spanId标识。
trace: 直接翻译就是追踪的意思。它由一系列的span组成。通常在第一个服务接收到请求时开启一个trace，生成一个唯一的traceId，后续的所有追踪都可以沿用这同一个traceId，这样就可以来唯一的标识这一整个调用链路。
annotation: 标记追踪过程中的一个事件，记录事件发生的时间。通过记录多个事件发生的时间就可以知道任意两个事件之间的耗时情况。Spring Cloud Sleuth默认会记录如下这几种事件。
（1）Client Sent: 客户端发送。记录客户端发起请求的时间，也是一个span的起点。
（2）Server Received: 服务端接收。记录服务端接收到请求的时间，它的时间减去客户端发送的时间就是客户端到服务端的网络时延。
（3）Server Sent: 服务端发送。记录服务端处理结束，进行结果响应的时间。它的时间减去服务端接收的时间就是服务端业务逻辑处理的时间。
（4）Client Received: 客户端接收。记录客户端完成整个请求，接收到服务端响应内容的时间。它的时间减去客户端发送的时间就是客户端发起请求到接收到服务端响应需要的时间。
（5）Tag: 标签，可以往span中添加一些Key、Value信息。

1.2. 日志
Spring Cloud Sleuth的追踪信息中的traceId、spanId会自动的添加到Slf4j的MDC中。所以如果你使用的日志框架是走的SLF4j规范的，则可以在日志中使用traceId、spanId变量。
spring 默认日志框架是 logback，这里就以 logback-spring.xml 为例，在 pattern 中添加变量 %X{traceId}、%X{spanId} 就能读到 MDC 中设置的 traceId、spanId 值。

X-B3-* 已被移除

要注意的是，网上一些示例用的是 %X{X-B3-TraceId}、%X{X-B3-SpanId} 来代替上面的值。经亲自踩坑，发现在 spring cloud sleuth 3.0.0 版本发布后，也可对应 spring cloud 2020.0.0 之后，X-B3- 这种写法已经被移除了。可能在其他地方还能见到，但在 MDC 中已经找不到了。

LOG_LEVEL_PATTERN

还有人要说了，我在引入了 sleuth之后，并没有创建 logback-spring.xml，也没有配置 traceId、spanId 这类值。或者创建了 logback-spring.xml，但 pattern 中没配置 traceId、spanId 的变量，为什么日志中也会打印出来呢，就像这样：

2022-02-20 23:01:28.662INFO [a-service,d0a7a4be9e9f3ab4,cb4cb09a83e0c553] 20570 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet: Initializing Servlet 'dispatcherServlet'

原因在于，当项目内没创建 logback-spring.xml 时，默认 pattern 中会包含 LOG_LEVEL_PATTERN 变量，类似于下面这个 logback-spring.xml：

DEBUG ${CONSOLE_LOG_PATTERN} utf8

而在 sleuth 框架里面有一个拓展处理类，会将 LOG_LEVEL_PATTERN 变量替换成 %5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}] 值。因此就算没设置 %X{traceId}等值，依然会显示。
TraceEnvironmentPostProcessor.java

public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) { Map map = new HashMap(); if (Boolean.parseBoolean(environment.getProperty("spring.sleuth.enabled", "true"))) { map.put("logging.pattern.level", "%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}]"); }this.addOrReplace(environment.getPropertySources(), map); }

2. MDC MDC(Mapped Diagnostic Contexts) ，翻译过来就是：映射的诊断上下文。意思是：在日志中（映射的）请求ID（requestId），可以作为我们定位（诊断）问题的关键字（上下文）。
2.1. 基础
有了MDC工具，只要在接口或切面植入 put 和 remove 代码，就可以在定位问题时，根据映射的唯一 requestID 快速过滤出某次请求的所有日志。另外，当客户端请求到来时，可以将客户端id，ip，请求参数等信息保存在MDC中，同时在logback.xml中配置，那么会自动在每个日志条目中包含这些信息。
MDC类基本原理其实非常简单，其内部持有一个ThreadLocal实例，用于保存context数据，MDC提供了put/get/clear等几个核心接口，用于操作ThreadLocal中的数据；ThreadLocal中的K-V，可以在logback.xml中声明，即在layout中通过声明 %X{Key} 来打印MDC中保存的此key对应的value在日志中。
例如下面定义过滤器

public class TraceFilter implements Filter { @Override public void init(FilterConfig filterConfig) throws ServletException { log.info("<<< 初始化TraceFilter>>>"); } @Override public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException { try { final HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest; String requestURI = httpServletRequest.getRequestURI(); MDC.put("requestURI", requestURI); // 放行 filterChain.doFilter(servletRequest, servletResponse); } finally { // 请求MDC 的内容 MDC.clear(); } } @Override public void destroy() { log.info("<<< 销毁TraceFilter>>>"); MDC.clear(); } }

配置logback-spring.xml

%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) [%X{requestURI}]%thread %logger Line:%-3L - %msg%n

在使用MDC时需要注意一些问题，这些问题通常也是ThreadLocal引起的，比如我们需要在线程退出之前清除（clear）MDC中的数据；在线程池中使用MDC时，那么需要在子线程退出之前清除数据；可以调用MDC.clear()方法。
slf4j的MDC机制其内部基于ThreadLocal实现，所以我们调用 MDC.put()方法传入的请求ID只在当前线程有效。所以，主线程中设置的MDC数据，在其子线程（线程池）中是无法获取的。那么主线程如何将MDC数据传递给子线程？官方建议:

在父线程新建子线程之前调用 MDC.getCopyOfContextMap() 方法将MDC内容取出来传给子线程。
子线程在执行操作前先调用 MDC.setContextMap() 方法将父线程的MDC内容设置到子线程。

例如下面的线程池：

public class ExecutorMDCTest { private static final AtomicInteger num = new AtomicInteger(1); static ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor( 5, 5 + 1, 60L, TimeUnit.SECONDS, new LinkedBlockingDeque<>(10_00), new ThreadFactory() { @Override public Thread newThread(Runnable r) {return new Thread(r, "test-thread" + num.getAndIncrement()); } }); static public void main(String[] args) throws Exception {Logger log = LoggerFactory.getLogger(ExecutorMDCTest.class); MDC.put("bl-traceid", "988f54f4bdd34920a53d908827a9fa59"); Map copyOfContextMap = MDC.getCopyOfContextMap(); // 线程池 threadPoolExecutor.execute(() -> { // 会丢失日志 log.info("测试打印日志4：{}", "data"); MDC.setContextMap(copyOfContextMap); log.info("设置后-测试打印日志5：{}", "data"); }); } }

配置logback-spring.xml

%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) [%X{bl-traceid}]%thread %logger Line:%-3L - %msg%n

2.2. Slf4j中的MDC
Slf4j MDC 内部实现很简单。实现一个单例对应实例，获取具体的MDC实现类，然后其对外接口，就是对参数进行校验，然后调用 MDCAdapter 的方法实现。MDCAdapter 是个接口类，当日志框架使用 Logback 时，对应接口的实现类就是 LogbackMDCAdapter，所以核心的实现类还是它，下面就列出代码：

public class LogbackMDCAdapter implements MDCAdapter { final ThreadLocal copyOnThreadLocal = new ThreadLocal(); private static final int WRITE_OPERATION = 1; private static final int MAP_COPY_OPERATION = 2; final ThreadLocal lastOperation = new ThreadLocal(); public LogbackMDCAdapter() { }private Integer getAndSetLastOperation(int op) { Integer lastOp = (Integer)this.lastOperation.get(); this.lastOperation.set(op); return lastOp; }private boolean wasLastOpReadOrNull(Integer lastOp) { return lastOp == null || lastOp == 2; }private Map duplicateAndInsertNewMap(Map oldMap) { Map newMap = Collections.synchronizedMap(new HashMap()); if (oldMap != null) { synchronized(oldMap) { newMap.putAll(oldMap); } }this.copyOnThreadLocal.set(newMap); return newMap; }public void put(String key, String val) throws IllegalArgumentException { if (key == null) { throw new IllegalArgumentException("key cannot be null"); } else { Map oldMap = (Map)this.copyOnThreadLocal.get(); Integer lastOp = this.getAndSetLastOperation(1); if (!this.wasLastOpReadOrNull(lastOp) && oldMap != null) { oldMap.put(key, val); } else { Map newMap = this.duplicateAndInsertNewMap(oldMap); newMap.put(key, val); }} }public void remove(String key) { if (key != null) { Map oldMap = (Map)this.copyOnThreadLocal.get(); if (oldMap != null) { Integer lastOp = this.getAndSetLastOperation(1); if (this.wasLastOpReadOrNull(lastOp)) { Map newMap = this.duplicateAndInsertNewMap(oldMap); newMap.remove(key); } else { oldMap.remove(key); }} } }public void clear() { this.lastOperation.set(1); this.copyOnThreadLocal.remove(); }public String get(String key) { Map map = (Map)this.copyOnThreadLocal.get(); return map != null && key != null ? (String)map.get(key) : null; }public Map getPropertyMap() { this.lastOperation.set(2); return (Map)this.copyOnThreadLocal.get(); }public Set getKeys() { Map map = this.getPropertyMap(); return map != null ? map.keySet() : null; }public Map getCopyOfContextMap() { Map hashMap = (Map)this.copyOnThreadLocal.get(); return hashMap == null ? null : new HashMap(hashMap); }public void setContextMap(Map contextMap) { this.lastOperation.set(1); Map newMap = Collections.synchronizedMap(new HashMap()); newMap.putAll(contextMap); this.copyOnThreadLocal.set(newMap); } }

值得注意的是，早期 LogbackMDCAdapter 类中定义 copyOnThreadLocal 的是 InheritableThreadLocal ，网上看到的很多资料都是说这种。InheritableThreadLocal 相较于 TreadLocal 的特点在于：InheritableThreadLocal 是对ThreadLocal 的扩展和继承，它的数据ThreadLocal.ThreadLocalMap保存在Thread的inheritableThreadLocals变量中，同时如果我们在当前线程开启一个新线程，而且当前线程存在inheritableThreadLocals变量，那么子线程会copy一份当前线程（父线程）中的这个变量持有的值。
但是在 LogbackMDCAdapter 中直接使用 InheritableThreadLocal 定义变量，默认都对子线程复制，影响性能，在如今最新版本已经改成 ThreadLocal 了。
3. sleuth原理 3.1. http跟踪
为了实现请求链路跟踪，当请求发送到分布式系统的入口时，只需要在服务跟踪框架为该请求创建唯一的跟踪标识，并保证该标识在在分布式系统内部流转，直到返回请求为止。该标识即为 traceId，通过该标识，就能将不同服务调用的日志串联起来。
为了统计各处理单元(应用服务)的延迟，当请求到达或处理逻辑达到某个状态时，也通过一个唯一标识来标记开始、具体过程及结束(标识一个服务内请求进入、处理到结束)，该标识即为 spanId。对于每个 spanId 来说，必须有开始和结束两个节点，通过计算开始 span 和结束 span 的时间戳，就能统记出该 span 的时间延迟。
而在 Http 请求链中，保障 traceId 在每个服务中传递的方式，是在基于 Http 的服务调用时，将 traceId 等信息通过 Http请求头传递过去。可以试验一下，在正常 feign 调用的下游方法中打印出所有请求头：

@GetMapping("/hello") public String hello(@RequestParam String name, @RequestHeader Map headers) { log.info("headers:{}", headers); }

日志内容如下，包含了参数： x-b3-traceid、x-b3-spanid、x-b3-parentspanid、x-b3-sampled=1。

headers:{x-b3-traceid=6dd57dc2ad55c58f, x-b3-spanid=b5e6de658b261ac7, x-b3-parentspanid=6dd57dc2ad55c58f, x-b3-sampled=1, accept=*/*, user-agent=Java/1.8.0_202, host=localhost:8081, connection=keep-alive}

在下游的服务接受调用时，sleuth 框架的 LazyTracingFilter 会做处理，从Http Request的Header里获取Span数据，如果Header中存在 x-b3-traceid、x-b3-spanid 等属性，就说明调用链前一个节点已经生成 span，并传递下来，这时可以直接使用这些span数据。否则，创建一个新的span。
3.2. 多线程跟踪
前面说 MDC 是基于 ThreadLocal 实现的，意味着当前线程存储的 traceId、spanId 等数据，在子线程将无法传递。但这样明显不符合我们期望的，根据一个 traceId 跟踪完整链路的想法。
还是基于前面的例子，在下游方法中打印：

@Resource private Executor asyncExecutor; @GetMapping("/hello") public String hello(@RequestParam String name, @RequestHeader Map headers) { log.info("headers:{}", headers); CompletableFuture.runAsync(() -> this.syncPrint(), asyncExecutor); log.info("exec:{}", asyncExecutor.toString()); }void syncPrint() { log.info("异步打印"); }// ... 配置类中定义 bean@Bean("asyncExecutor") public Executor getAsyncExecutor() { ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor(); threadPoolTaskExecutor.setCorePoolSize(7); threadPoolTaskExecutor.setMaxPoolSize(42); threadPoolTaskExecutor.setQueueCapacity(11); threadPoolTaskExecutor.setThreadNamePrefix("MyExecutor-"); threadPoolTaskExecutor.initialize(); return threadPoolTaskExecutor; }

打印的结果是：

2022-02-28 23:14:40.711INFO [a-service,14b328adfec294a8,739f0082a7cbaa19] 23400 --- [nio-8081-exec-1] p.k.aservice.controller.HelloController: headers:{x-b3-traceid=14b328adfec294a8, x-b3-spanid=739f0082a7cbaa19, x-b3-parentspanid=14b328adfec294a8, x-b3-sampled=1, accept=*/*, user-agent=Java/1.8.0_202, host=localhost:8081, connection=keep-alive}2022-02-28 23:14:40.718INFO [a-service,14b328adfec294a8,739f0082a7cbaa19] 23400 --- [nio-8081-exec-1] p.k.aservice.controller.HelloController: exec:org.springframework.cloud.sleuth.instrument.async.LazyTraceThreadPoolTaskExecutor@728640832022-02-28 23:14:40.720INFO [a-service,14b328adfec294a8,060fcae6ba359b01] 23400 --- [MyExecutor-1] p.k.aservice.controller.HelloController: 异步打印

其实我还做了几个实验，最终打印的结果相同：

如果代码中没有注册 asyncExecutor 的 bean，直接使用 Spring 默认的线程池，打印出来的结果还是一样。
如果代码中没有使用 CompletableFuture.runAsync 来执行异步方法，而是将方法写在另外的类，通过 @Async 调用，打印出来的结果还是一样。

要想找到原因，就从 asyncExecutor.toString() 打印出来的结果入手：org.springframework.cloud.sleuth.instrument.async.LazyTraceThreadPoolTaskExecutor@72864083。通过搜索源码，发现 sleuth 框架定义了自动配置，会将 spring 容器中注册的线程池 bean 代理成 LazyTraceThreadPoolTaskExecutor，而 LazyTraceThreadPoolTaskExecutor 这个框架自定义的线程池能实现对 traceId 等信息的传递。
开启代理通过配置参数 spring.sleuth.async.enabled，因为默认值即 true，因此默认开启。如果部分自定义线程的 bean 不想如此代理，还可以配置 spring.sleuth.async.ignored-beans。
不过如果将上述代码中异步打印部分改成

CompletableFuture.runAsync(() -> this.syncPrint());

，打印的结果是：

2022-02-28 23:14:40.715INFO [a-service,,] 23400 --- [onPool-worker-1] p.k.aservice.controller.HelloController: 异步打印

原因在于此时并没有使用 spring 容器中的线程池 bean，而是默认使用 jdk 中的 ForkJoinPool.commonPool()，因为并未被代理。
3.3. 配合 zipkin 使用
通俗来说，zipkin server 采集 sleuth 在客户端的数据，并提供可视化界面做查询展示。
这里用 docker 简单启一个 zipkin server：

docker run -d \ --name zipkin \ --restart=on-failure:3 \ -p 9411:9411 \ openzipkin/zipkin

pom.xml中引入zipkin客户端依赖：

org.springframework.cloud spring-cloud-sleuth-zipkin

application.properties 中配置 zipkin server 地址：

spring.zipkin.base-url=http://localhost:9411

这样就好了，正常运行包含 sleuth 的项目后，在浏览器中访问地址：http://localhost:9411 ，就进入了 zipkin 界面。并且可以查询链路日志。
当然 zipkin 的实际配置没这么简单，它要做 sleuth 的数据采样，往往还要和 MQ 配合使用。但这些不是本文重点，况且如今也很少有公司选择 zipkin。
4. 补充方案设想 sleuth 实现全链路日志的方案比较清晰，回头看前面的问题：

如今排查问题，首先就是找到该次请求的 traceId，然后就可以从 elk 中捞任何我想要的日志了。当查到调用其他服务报错的日志时，直接拿着 traceId 联系负责下游服务的团队即可。
性能优化时，可以通过图形化界面看到每个 span 的处理时间。从而一目了然地定位到性能瓶颈处。

但实际项目中，针对有些应用场景，原生的 sleuth 也是鞭长莫及。但我们可以模仿它的实现方案做一些补充方案：

MQ 的链路日志

有些业务场景中，我希望能将 MQ 的生产者和消费者连起来，通过生产者的 traceId，也能看到消息被消费的链路日志。
这里应该可以类似 http 的做法，生产者发送消息时将 traceId 等数据放入消息头中，当消费者接收消息时从消息头中获取，作为 traceId 继续传递。

异常 Response属性

很多人都会在项目中基于 ExceptionHandler 做同一异常处理，返回体中一般都会包含状态码、常见错误内容等关键信息。但既然是异常处理，最重要的就是排查错误，应该必须包含 traceId。

自定义链路追踪

【微服务的全链路日志】基于 sleuth、zipkin 的实现方案，我们是不是可以自己开发一套定制的全链路日志方案呢？

可以不用像 sleuth 有很细的粒度，例如基于线程的 span 等。我们只记录单个微服务请求、mq消费等粗粒度的参数。
还是基于请求头来传递 traceId，在服务请求、响应处做拦截器，服务调用时做 aop，以及异常日志的捕获等，然后将日志信息上传给负责链路日志收集的服务来处理。
单独开发一个记录链路日志的微服务，一方面搜集所有微服务埋点处上传的日志，另一方面做自定义的数据分析。例如：可以像 zipkin一样通过 traceId 查询全链路日志；还可以做性能分析看板，找出请求时间长的链路、报错的链路、调用最频繁的服务等等。当问题到达阈值，甚至可以给运维人员做消息推送。