Dubbo日志链路追踪TraceId选型

Posted 2023-05-15

参考技术A

开发排查系统问题用得最多的手段就是查看系统日志，但是在分布式环境下使用日志定位问题还是比较麻烦，需要借助 全链路追踪ID 把上下文串联起来，本文主要分享基于 Spring Boot + Dubbo 框架下 日志链路追踪ID 的实现方案选型思路。

 

目前大多数分布式追踪系统的思想模型都来自 Google\'s Dapper 论文

全链路追踪的核心思想：

 

这是 SkyWalking 的一个日志插件，通过这个插件可以在日志中输出
traceId

配置依赖 ，在 pom 文件中添加以下内容

 

配置日志模板 ，修改 logback-spring.xml 文件中 Appender 元素的 encoder 为以下内容

 

 

Sleuth 是 Spring Cloud 的组件之一，它为 Spring Cloud 实现了一种分布式追踪解决方案，兼容Zipkin，HTrace与其他日志追踪系统

配置父依赖 ，在 pom 文件中添加以下内容管理版本号

 

配置依赖 ，在 pom 文件中添加以下内容

 

适配dubbo ，要让 sleuth 支持 dubbo 框架，需要增加以下两个步骤：

首先添加 dubbo 的插件依赖

配置 dubbo 过滤器

 

配置日志模板 ，修改 logback-spring.xml 文件中 Appender 元素的 encoder 为以下内容

 

 

使用 Logback 的 MDC 机制，在日志模板中加入 traceId 标识，取值方式为 %XtraceId

 

解决 traceId 跨线程丢失问题

由于 MDC 内部使用的是 ThreadLocal 所以只有本线程才有效，子线程和下游的服务 MDC 里的值会丢失；

需要解决 Spring 的各种线程池与异步方法的父子线程间传递。

解决思路 ：重写一个 MDCAdapter 使用阿里的 TransmittableThreadLocal 替换原来的 ThreadLocal 对象，解决各种线程池（ ExecutorService / ForkJoinPool / TimerTask ）父子进程传值问题。

 

解决 traceId 跨进程丢失问题

dubbo服务 使用 org.apache.dubbo.rpc.Filter 创建一个过滤器进行 traceId 传递

 

 

zipkin链路追踪

zipkin架构说明

3个主要概念

（1）Trace：它是由一组有相同Trace ID的Span串联形成一个树状结构。为了实现请求跟踪，当请求请求到分布式系统的入口端点时，只需要服务跟踪框架为该请求创建一个唯一的跟踪标识（即前文提到的Trace ID），同时在分布式系统内部流转的时候，框架始终保持传递该唯一标识，直到返回请求为止，我们通过它将所有请求过程中的日志关联起来；
（2）Span：它代表了一个基础的工作单元，例如服务调用。为了统计各处理单元的时间延迟，当前请求到达各个服务组件时，也通过一个唯一标识（即前文提到的Span ID）来标记它的开始、具体过程以及结束。通过span的开始和结束的时间戳，就能统计该span的时间延迟，除此之外，我们还可以获取如事件名称、请求信息等元数据。
（3）Annotation：它用于记录一段时间内的事件。内部使用的最重要的注释是：

cs - Client Sent - 客户端发送一个请求，这个注解描述了这个Span的开始。
sr - Server Received - 服务端获得请求并准备开始处理它，其中（sr – cs） 时间戳便可得到网络传输的时间。
ss - Server Sent （服务端发送响应）– 该注解表明请求处理的完成(当请求返回客户端)， （ss – sr）时间戳就可以得到服务器请求的时间。
cr - Client Received （客户端接收响应）- 表明此时Span的结束，（cr – cs）时间戳便可以得到整个请求所消耗的时间。

一个例子

上图表示一请求链路，一条链路通过Trace Id唯一标识，Span标识发起的请求信息，各span通过parent id 关联起来，如图

整个链路的依赖关系如下:

sr-cs 得到请求发出延迟
ss-sr 得到服务端处理延迟
cr-cs 得到真个链路完成延迟

日志格式

zipkin官网的一个流程图

官网翻译

Instrumented client:被装配的客户端
Non-Instrumented server:没被装配的服务端
Instrumented server:被装配的服务端

你所在平台是否已经有现成的装配库，可以查看：现有的装配库

┌─────────────┐ ┌───────────────────────┐  ┌─────────────┐  ┌──────────────────┐
│ User Code   │ │ Trace Instrumentation │  │ Http Client │  │ Zipkin Collector │
└─────────────┘ └───────────────────────┘  └─────────────┘  └──────────────────┘
       │                 │                         │                 │
           ┌─────────┐
       │ ──┤GET /foo ├─? │ ────┐                   │                 │
           └─────────┘         │ record tags
       │                 │ ?───┘                   │                 │
                           ────┐
       │                 │     │ add trace headers │                 │
                           ?───┘
       │                 │ ────┐                   │                 │
                               │ record timestamp
       │                 │ ?───┘                   │                 │
                             ┌─────────────────┐
       │                 │ ──┤GET /foo         ├─? │                 │
                             │X-B3-TraceId: aa │     ────┐
       │                 │   │X-B3-SpanId: 6b  │   │     │           │
                             └─────────────────┘         │ invoke
       │                 │                         │     │ request   │
                                                         │
       │                 │                         │     │           │
                                 ┌────────┐          ?───┘
       │                 │ ?─────┤200 OK  ├─────── │                 │
                           ────┐ └────────┘
       │                 │     │ record duration   │                 │
            ┌────────┐     ?───┘
       │ ?──┤200 OK  ├── │                         │                 │
            └────────┘       ┌────────────────────────────────┐
       │                 │ ──┤ asynchronously report span     ├────? │
                             │                                │
                             │{                               │
                             │  "traceId": "aa",              │
                             │  "id": "6b",                   │
                             │  "name": "get",                │
                             │  "timestamp": 1483945573944000,│
                             │  "duration": 386000,           │
                             │  "annotations": [              │
                             │--snip--                        │
                             └────────────────────────────────┘