分布式系统故障排查：调用链追踪利器MDC侦探详解

前言

日常工作中排查线上问题，经常会遇到一些问题：

线上系统某次调用异常，是哪笔订单的什么操作造成的？是哪个服务调用的？来自哪台机子？
异常订单操作，对数据有哪些造成了影响？
用户在某个时段分别进行了哪些操作?

而日趋复杂的分布式系统，

微服务
分布式中间价：消息队列、分布式缓存、分布式对象存储
不同调用：跨机房、跨区域调用、第三方调用

❝

调用链作为排查问题的核心，通过其可以将各类数据关联在一起，提高问题排查能力。

啥是MDC？

MDC（Mapped Diagnostic Context，映射调试上下文）是日志框架（如log4j、logback等）提供的一种功能，允许开发者在日志消息中嵌入额外的上下文信息。这些信息可以在日志处理过程中跨多个日志语句和跨多个线程传递，非常适合用于链路追踪。在微服务架构中，MDC成为了调用链追踪的利器，帮助开发者追踪请求在整个系统中的处理流程。

它可以在日志消息中存储上下文消息，在日志事件之间传播键值。

MDC 的 API 说明

MDC 提供了一系列 API 用于操作上下文信息，主要包括以下几个方法：

• clear()：移除当前线程 MDC 中的所有信息。 • get(String key)：获取当前线程 MDC 中指定 key 的值。 • put(String key, Object o)：往当前线程的 MDC 中存入指定的键值对。 • remove(String key)：删除当前线程 MDC 中指定的键值对。

这些 API 使得开发者能够在代码中灵活地添加、获取和删除 MDC 中的信息，从而实现对日志上下文的精确控制。

MDC 在调用链追踪中的应用

在调用链追踪中，MDC 的应用主要体现在以下几个方面：

生成并传递traceId：

在请求的入口点（如网关或 API 接口），通过拦截器生成一个全局唯一的 traceId，并将其放入 MDC 中。

在服务间的调用中，通过 HTTP 请求的 Header 传递 traceId，接收方服务在接收到请求后，从 Header 中提取 traceId 并放入 MDC 中。

配置日志格式：

在日志框架的配置文件中，配置日志格式以包含 MDC 中的 traceId。这样，在记录日志时，就会自动将 traceId 嵌入到日志消息中。

跨线程传递：

在多线程处理请求的场景下，需要确保子线程能够继承父线程的 MDC 内容。这通常需要对线程池进行配置，使其支持 InheritableThreadLocal。

MDC 的优势与注意事项

优势：

轻量级：MDC 的实现相对简单，对系统性能的影响较小。
灵活性：MDC 允许程序在运行时动态地添加和修改上下文信息，满足不同的追踪需求。
易用性：通过简单的配置和 API 调用，即可实现调用链的追踪和日志的集中管理。

注意事项：

线程隔离：MDC 是与当前线程绑定的，因此在多线程环境下需要特别注意 traceId 的传递。
安全性：避免在 MDC 中存储敏感信息，以防泄露。
性能考虑：虽然 MDC 对系统性能的影响较小，但在高并发场景下仍需关注其对性能的可能影响。

快速入门

在 pom.xml 中添加 logback-classic 依赖

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

在 logback.xml中配置日志信息

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %mdc - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

<PatternLayout pattern="[%date{yyyy-MM-dd HH:mm:ss,SSS}] [%level] [%C{1}:%line] [%thread] [%traceId] -- %mdc{operator} %mdc{request} %m%n"/>。

通过 MDC 设置 key

@Component
public class RequestInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String userId = request.getHeader("traceId");
        MDC.put("traceId", traceId);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        MDC.remove("traceId");
    }
}

啥是traceId ？

traceId：用于标识某一次具体的请求ID。通过 traceId 来将一个请求在各个服务器上的调用日志串联起来。

traceId 一般由接收请求经过的第一个服务产生。

traceId 与 spanId 区别：

traceId 是用于串联某一次请求在系统中经过的所有路径
spanId是用于区分系统不同服务之间调用的先后关系

traceId 生成规则

SkyWalking里TraceId 组成规则：

https://github.com/apache/skywalking/blob/f3ca0d0ea52bf05df87e9b1e268b7f5d69423a88/apm-sniffer/apm-agent-core/src/main/java/org/apache/skywalking/apm/agent/core/context/ids/GlobalIdGenerator.java#L78

这里我们参考阿里的鹰眼组件的 TraceId 生成的规则。

生成规则如下：服务器 IP + ID 产生的时间 + 自增序列 + 当前进程号，比如：

0ad1348f1403169275002100356696
共 30 位

0	1	2	3	4	5	6	7	8	9	10	11	12	13	14	15	16	17	18	19	20	21	22	23	24	25	26	27	28	29
服务器IP，十六进制：0ad1348f	时间戳，1403169275002	自增序列，1003	当前进程ID

前8位：0-7，产生 TraceId 的机器的 IP，这是一个十六进制的数字，每两位代表 IP 中的一段。
按每两位转成 10 进制即可得到常见的 IP 地址表示方式 10.209.52.143
再13位：8-20，产生 TraceId 的时间
再4位：自增的序列，从 1000 -> 9000，到9000后再回到 1000
最后5位：当前的进程 ID，防止单机多进程出现 TraceId 冲突的情况
Thread.currentThread().getId();

最佳实践

前端交互

❝

前端与后端交互，诉求只想知道这次调用对应后端哪次调用链，方便排查问题。所以只需要告诉前端，这次请求的 traceId 是多少。

traceId：一般会在返回体的 Header 和 Body 中体现。

举个 🌰 栗子，在 HTTP 的 Response 的 Header中体现：X-Tracking-Id。

举个 🌰 栗子，在 HTTP 的 Response 的 Body 中体现：traceId

{
    "code": 0,
    "success": true,
    "message": null,
    "traceId": "933ce7302b0b4396a89b1a81747b0e46",
    "data": {}
}

服务间交互

服务间交互：Feign、Dubbo

Feign 请求拦截器中塞入 traceId：

@Slf4j
public class FeignRequestInterceptor extends BasicAuthRequestInterceptor {
    @Override
    public void apply(RequestTemplate template) {

        template.header("X-Tracking-ID", MDC.get("traceId"));
    }
}

Dubbo 消费者获取 traceId：

@Slf4j
@Activate(group = {Constants.CONSUMER}, order = -99999)
public class TrackIdConsumerFilter implements Filter {

    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String tid = MDC.get("traceId");
        if (StringUtils.isBlank(tid)) {
            tid = UUIDUtils.UUID32();
        }
        RpcContext.getContext().setAttachment("traceId", tid);
        return invoker.invoke(invocation);
    }

    @Override
    public Result onResponse(Result result, Invoker<?> invoker, Invocation invocation) {
        return Filter.super.onResponse(result, invoker, invocation);
    }
}

Dubbo 生产者塞入 traceId：

@Slf4j
@Activate(group = {Constants.PROVIDER}, order = -99999)
public class TrackIdProviderFilter implements Filter {

    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String tid = invocation.getAttachment("traceId");
        if (StringUtils.isBlank(tid)) {
            tid = UUIDUtils.UUID32();
        }
        MDC.put("traceId", tid);
        try {
            return invoker.invoke(invocation);
        } finally {
            MDC.clear();
        }
    }

    @Override
    public Result onResponse(Result result, Invoker<?> invoker, Invocation invocation) {
        return Filter.super.onResponse(result, invoker, invocation);
    }
}

（2）MQ消息 / XXL-JOB 传递

这类可以封装对应注解，用 AOP 来统一处理下。

注解：@TraceId
AOP：TraceIdAspect

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface XTraceId {
}
@Aspect
@Component
@Slf4j
public class TraceIdAspect {
    @Pointcut("@annotation(com.server.annotation.TraceId)")
    public void annotationPointCut() {
    }

    @Around("annotationPointCut()")
    public Object doAround(ProceedingJoinPoint pjp) throws Throwable {
        String traceId = UUIDUtils.nextId("");
        MDC.put("traceId", traceId);
        try {
            return pjp.proceed();
        } finally {

            MDC.remove("traceId");
        }
    }
}

举个 🌰 栗子，在 RocketMQ 中消息者消费消息时：

消费者执行消息时，用 traceId 把单次调用链串联起来。

@Slf4j
@Component
@RequiredArgsConstructor
public class ConsumerListener implements MessageListener {
    @TraceId
    @Override
    public Action consume(Message message, ConsumeContext context) {
        try {
            // 业务处理
            return Action.CommitMessage;
        } catch (Exception e) {
            // 异常处理
            return Action.ReconsumeLater;
        }
    }
}

举个 🌰 栗子，XXL-JOB 中使用：

@Slf4j
@Component
@JobHandler
@RequiredArgsConstructor
public class PushXXRobotContactJob extends IJobHandler {
    // 加上注解
    @TraceId
    @Override
    public ReturnT<String> execute(String param) {
        return ReturnT.SUCCESS;
    }
}

（3）多线程（父子线程）

由于 MDC 是基于 ThreadLocal 实现，上下文信息是线程私有的，并且 ThreadLocal 变量具有不继承性，所以如果代码中使用了多线程，traceId 是无法自动传递的。

官方建议： https://logback.qos.ch/manual/mdc.html。

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

方式一：使用 Decorator

public class TraceIdTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> context = MDC.getCopyOfContextMap();
        
        return () -> {
            try {
                MDC.setContextMap(context);
                
                runnable.run();
            } finally {
                
                MDC.clear();
            }
        };
    }
}

🌰 栗子1： @Async

@Slf4j
@Configuration
@EnableAsync
public class AsyncConfig implements AsyncConfigurer {

    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(3);
        executor.setMaxPoolSize(10);
        executor.setQueueCapacity(100);
        executor.setThreadNamePrefix("AsyncThread-");
        executor.setTaskDecorator(MdcTaskDecorator::new);
        executor.initialize();
        return executor;
    }

    private static class MdcTaskDecorator implements Runnable {

        private final Runnable delegate;

        public MdcTaskDecorator(Runnable delegate) {
            this.delegate = delegate;
        }

        @Override
        public void run() {
            String traceId = MDC.get("traceId");
            if (StringUtils.isNotBlank(traceId)) {
                MDC.put("traceId", traceId);
            }
            try {
                delegate.run();
            } finally {
                MDC.clear();
            }
        }
    }
}

方式二：使用 InheritableThreadLocal 对象

public class UserInheritableUtils {
    private static final InheritableThreadLocal<String> THREAD_LOCAL = new InheritableThreadLocal<>();

    public static String get(){
        return THREAD_LOCAL.get();
    }
    public static void set(String val){
        THREAD_LOCAL.set(val);
    }

    public static void clear(){
        THREAD_LOCAL.remove();
    }
}

ThreadLocal 变量的不继承性

在使用 ThreadLocal 存储本地变量时，主线程与子线程之间不具有继承性。

在主线程中使用 ThreadLocal 对象保存本地变量后，无法通过同一个 ThreadLocal 对象获取到主线程中保存的只。

![图片](data:image/svg+xml,%3C%3Fxml version='1.0' encoding='UTF-8'%3F%3E%3Csvg width='1px' height='1px' viewBox='0 0 1 1' version='1.1' xmlns='http://www.w3.org/2000/svg' xmlns:xlink='http://www.w3.org/1999/xlink'%3E%3Ctitle%3E%3C/title%3E%3Cg stroke='none' stroke-width='1' fill='none' fill-rule='evenodd' fill-opacity='0'%3E%3Cg transform='translate(-249.000000, -126.000000)' fill='%23FFFFFF'%3E%3Crect x='249' y='126' width='1' height='1'%3E%3C/rect%3E%3C/g%3E%3C/g%3E%3C/svg%3E)

🌰 栗子1：子线程获取主线程的值

public class ThreadLocalTest {
    private static final ThreadLocal<String> THREAD_LOCAL = new ThreadLocal<>();

    public static void main(String[] args) {
        THREAD_LOCAL.set("main_thread_donald"); // 主线程保存值

        new Thread(() -> {
            // 子线程获取对应的值
            System.out.println("在子线程中获取到的本地变量的值为：" + THREAD_LOCAL.get());
        }).start();

        System.out.println("在主线程中获取到的本地变量的值为：" + THREAD_LOCAL.get());
    }
}

输出结果如下：

结论：在主线程中通过 ThreadLocal 对象保存值后，在子线程中通过相同的 ThreadLocal 对象是无法获取到这个值的。

在主线程中获取到的本地变量的值为：main_thread_donald
在子线程中获取到的本地变量的值为：null

Process finished with exit code 0

🌰 栗子2：InheritableThreadLocal 使用

如果需要在子线程中获取到主线程中保存的值，则可以使用 InheritableThreadLocal 对象。

public class InheritableThreadLocalTest {
    private static final ThreadLocal<String> THREAD_LOCAL = new InheritableThreadLocal<>();

    public static void main(String[] args) {
        THREAD_LOCAL.set("main_thread_donald"); // 主线程保存值

        new Thread(() -> {
            // 子线程获取对应的值
            System.out.println("在子线程中获取到的本地变量的值为：" + THREAD_LOCAL.get());
        }).start();

        System.out.println("在主线程中获取到的本地变量的值为：" + THREAD_LOCAL.get());
    }
}

输出结果如下：

结论：在主线程中通过 InheritableThreadLocal 对象保存值后，在子线程中通过相同的 InheritableThreadLocal 对象是可以获取到这个值的。

在主线程中获取到的本地变量的值为：main_thread_donald
在子线程中获取到的本地变量的值为：main_thread_donald

Process finished with exit code 0

（4）sls 接入日志/查看

日常工作中，查询日志依赖阿里云的 sls。排查问题，会跟根据告警信息中的 traceId 进行查询。

接收告警信息：文本中带有 traceId
根据 traceId 查询调用链

后记

鄙人认为MDC这个还是比较重要的，我们公司最早使用MDC是为了解决 RocketMQ发送和消费之间的日志查询。

在项目中重写 RocketMQ客户端在发送消息前取出MDC中的TraceID 放到MQ的参数中消费的时候再把TraceID从参数中取出来在放到MDC中这样方便排查问题。

来源：https://juejin.cn/post/7410951286861316134