手写链路追踪优化-MDC改造

1. 前文回顾和优化需求分析

前面三篇文章已经让《手写链路追踪》有一定适应能力了
前文1：手写链路追踪
前文2：手写链路追踪优化-自动全局追踪代替局部手动追踪
前文3：手写链路追踪优化-多线程追踪
我们前面的努力虽然能实现日志追踪了，但是在api请求中用trace id替换线程名，我们无法在日志中看到线程名了，我们先来看看日志中有线程名的好处吧。

1.1 线程名本身也可以做为一个trace id，是请求追踪的核心标识

用于：

  • 关联同一请求的所有日志：即使请求经过多个服务或线程，都能通过traceId关联
  • 问题排查：快速定位特定请求的所有处理过程
  • 性能分析：跟踪请求在系统中的完整处理路径和耗时

1.2 线程名包含线程类型信息

默认线程名包含的信息

  • 线程池类型：如http-nio-8080-exec-5表示HTTP处理线程
  • 线程编号：帮助识别并发处理情况
  • 线程用途：区分不同用途的线程（HTTP、异步、定时任务等)

1.3 并发处理信息

识别并发问题
通过线程名可以识别：

  • 并发处理数量：同时处理多少个请求
  • 线程竞争：是否存在线程阻塞或竞争
  • 负载分布：请求在不同线程间的分布情况

1.4 异步处理追踪

跨线程追踪
在异步处理场景中，线程名帮助：

  • 跟踪异步任务：从主线程到异步线程的完整调用链
  • 关联父子线程：虽然使用了InheritableThreadLocal，但线程名提供了额外的可视化信息

1.5 调试和监控价值

问题诊断

  • 请求路径追踪：快速查看请求经过的所有组件
  • 性能瓶颈定位：识别处理慢的环节
  • 异常影响范围：确定异常影响的请求范围

监控分析

  • 请求流量统计：通过traceId统计独立请求量(线程名和trace id 联合使用)
  • 服务依赖分析：分析服务间的调用关系
  • 错误模式识别：识别特定类型请求的错误模式

1.6 总结

综合以上分析，线程名在日志追踪里面有举足重轻的作用，我们应该在日志里面保留线程名，如果能再加入一个串连上下游服务的trace id，那就更理想了。接下来我准备用MDC来实现它, 我们先来了解一下什么是MDC。

2. 什么是MDC

MDC（Mapped Diagnostic Context，映射调试上下文）是日志框架（如Log4j、Logback）提供的一个功能，用于在日志输出中添加诊断信息。

2.1 MDC的基本概念

定义

MDC是NDC（Nested Diagnostic Context）的改进版本，它允许开发者以键值对的形式将诊断信息存储在当前线程中，这些信息会自动包含在该线程生成的所有日志消息中。

核心特点

  • 线程本地存储：每个线程都有独立的MDC副本
  • 自动传播：与InheritableThreadLocal类似，子线程可以继承父线程的MDC
  • 日志集成：日志框架自动从MDC中获取信息并添加到日志输出中

2.2 MDC vs ThreadLocal

特性 MDC ThreadLocal
用途 专门为日志诊断设计 通用线程本地存储
日志集成 原生支持，无需额外配置 需要手动处理
自动输出 日志框架自动包含在日志中 需要显式获取和使用
清理机制 框架自动管理部分资源 需要手动清理

2.3. MDC的使用方法

基本操作

import org.slf4j.MDC;

// 设置诊断信息
MDC.put("traceId", "abc123def456");
MDC.put("userId", "user123");

// 获取诊断信息
String traceId = MDC.get("traceId");

// 移除诊断信息
MDC.remove("traceId");

// 清空所有诊断信息
MDC.clear();

2.4 MDC在分布式追踪中的应用

多维度追踪信息

// 可以存储多个诊断信息
MDC.put("traceId", "abc123def456");     // 全局追踪ID
MDC.put("spanId", "xyz789");            // 当前操作ID
MDC.put("userId", "user123");           // 用户ID
MDC.put("requestUri", "/api/login");    // 请求路径

日志输出效果

2025-08-30 10:15:23.123 [http-nio-8080-exec-5] [traceId=abc123def456] [spanId=xyz789] [userId=user123] INFO  c.s.l.c.LoginController - processing login

2.5 注意事项

  1. 及时清理：必须在请求结束时调用MDC.clear()防止内存泄漏
  2. 异步处理：在异步线程中需要重新设置MDC
  3. 线程池：使用线程池时要特别注意MDC的清理
  4. 性能影响：MDC操作非常轻量，性能影响可以忽略

MDC是实现分布式链路追踪的标准做法，相比直接修改线程名更加规范和灵活。
MDC已经了解这么多了，接下来我们看看怎么用它来给我的链路追踪做优化吧。

3. 用MDC实现链路追踪的优化

3.1 添加一个MDC工具类

添加一个工具类，避免调用MDC的时候到处使用"traceId" key的魔法值

package com.sandwich.logtracing.util;

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/8/31
 * @Description: MDC工具类
 */
public class MdcUtils {
    public static final String TRACE_ID = "traceId";

    public static void setTraceId(String traceId) {
        if (StringUtils.isBlank(traceId)) {
            setTraceId();
            return;
        }
        MDC.put(TRACE_ID, traceId);
    }

    public static void setTraceId() {
        String traceId = RandomStrUtils.generateRandomString(15);
        MDC.put(TRACE_ID, traceId);
    }

    public static String getTraceId() {
        return MDC.get(TRACE_ID);
    }

    public static void removeTraceId() {
        MDC.remove(TRACE_ID);
    }
}

3.2 ThreadLocalContext增加一些清除trace id的日志

package com.sandwich.logtracing.util;

import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.StringUtils;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/8/30
 * @Description: 这是一个用于在线程间存储和传递追踪ID（traceId）的上下文工具类，主要目的是实现请求链路追踪。
 */
@Slf4j
public class ThreadLocalContext {
    /**
     * 线程本地存储，用于存储追踪ID
     * 使用 InheritableThreadLocal 而不是普通的 ThreadLocal
     * InheritableThreadLocal 允许子线程继承父线程的值，这对于异步处理场景非常重要
     */
    private static final InheritableThreadLocal<String> TRACE_ID = new InheritableThreadLocal<>();

    public static String getTraceId() {
        return TRACE_ID.get();
    }

    public static void setTraceId(String traceId) {
        TRACE_ID.set(traceId);
    }

    /**
     * 清除当前线程的traceId，防止内存泄漏
     */
    public static void clearTraceId() {
        if (StringUtils.isBlank(TRACE_ID.get())) {
            log.info("traceId is empty from thread local already");
            return;
        }
        TRACE_ID.remove();
        log.info("traceId removed from thread local");
    }
}

3.3 Filter改造

package com.sandwich.logtracing.filter;

import com.sandwich.logtracing.util.MdcUtils;
import com.sandwich.logtracing.util.RandomStrUtils;
import com.sandwich.logtracing.util.ThreadLocalContext;
import jakarta.servlet.*;
import lombok.extern.slf4j.Slf4j;
import org.apache.catalina.connector.RequestFacade;
import org.apache.commons.lang3.StringUtils;

import java.io.IOException;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/8/30
 * @Description: log filter, to update the log thread name with a trace id
 */
@Slf4j
public class LogFilter implements Filter {
    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        String traceId = ((RequestFacade) servletRequest).getHeader("x-request-correlation-id");
        //if the request header don't have a trace id，then generate a random one
        if (StringUtils.isBlank(traceId)) {
            traceId = RandomStrUtils.generateRandomString(15);
        }
        try {
            //set trace id to mdc
            MdcUtils.setTraceId(traceId);
            //set trace id to thread local
            ThreadLocalContext.setTraceId(traceId);
            filterChain.doFilter(servletRequest, servletResponse);
        } finally {
            //remove trace id from thread local for main thread
            ThreadLocalContext.clearTraceId();
            //remove trace id from mdc
            MdcUtils.removeTraceId();
        }
    }
}

注意finally里面清除thread local里面的trace id先，再清除MDC里面的trace id, 否则清除thread local trace id的日志会缺少trace id 值。

3.4 Aspect改造

package com.sandwich.logtracing.aspect;

import com.sandwich.logtracing.util.MdcUtils;
import com.sandwich.logtracing.util.ThreadLocalContext;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

/**
 * @Author 公众号： IT三明治
 * @Date 2025/8/30
 * @Description: 这是一个用于在异步线程中保持traceId一致性的AOP切面，主要目的是在使用@Async注解的方法执行时，将主线程中的traceId传递到异步线程中
 * 主线程是父线程，异步线程是子线程, 因此需要使用ThreadLocal来保存traceId, 以便在异步线程中保持一致性
 */
@Slf4j
@Aspect
@Component
public class TraceIdAspect {

    @Around("@annotation(org.springframework.scheduling.annotation.Async)")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        String traceId = ThreadLocalContext.getTraceId();
        if (traceId == null) {
            // 执行目标方法并返回
            return joinPoint.proceed();
        }

        try {
            MdcUtils.setTraceId(traceId);
            // 执行目标方法并返回
            return joinPoint.proceed();
        } finally {
            // clear trace id from thread local
            ThreadLocalContext.clearTraceId();
            // remove trace id from mdc
            MdcUtils.removeTraceId();
        }
    }
}

注意finally里面清除thread local里面的trace id先，再清除MDC里面的trace id, 否则清除thread local trace id的日志会缺少trace id 值, 这里跟filter一样。

3.5 API改造

3.6 添加日志管理文件（logback-spring.xml）

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 属性配置 -->
    <property name="LOG_HOME" value="./logs"/>
    <property name="APP_NAME" value="log-tracing"/>
    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{traceId}] %-5level %logger{50} - %msg%n"/>
    <property name="MAX_FILE_SIZE" value="100MB"/>
    <property name="MAX_HISTORY" value="30"/>

    <!-- 控制台输出 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- INFO级别日志文件 -->
    <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_HOME}/${APP_NAME}-info.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/${APP_NAME}-info.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>${MAX_FILE_SIZE}</maxFileSize>
            <maxHistory>${MAX_HISTORY}</maxHistory>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- WARN级别日志文件 -->
    <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_HOME}/${APP_NAME}-warn.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/${APP_NAME}-warn.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>${MAX_FILE_SIZE}</maxFileSize>
            <maxHistory>${MAX_HISTORY}</maxHistory>
            <totalSizeCap>5GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- ERROR级别日志文件 -->
    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_HOME}/${APP_NAME}-error.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/${APP_NAME}-error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>${MAX_FILE_SIZE}</maxFileSize>
            <maxHistory>${MAX_HISTORY}</maxHistory>
            <totalSizeCap>5GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- 全量日志文件 -->
    <appender name="ALL_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_HOME}/${APP_NAME}-all.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/${APP_NAME}-all.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>${MAX_FILE_SIZE}</maxFileSize>
            <maxHistory>${MAX_HISTORY}</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!-- 异步包装器 -->
    <appender name="ASYNC_INFO" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <includeCallerData>false</includeCallerData>
        <appender-ref ref="INFO_FILE"/>
    </appender>

    <appender name="ASYNC_WARN" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <includeCallerData>false</includeCallerData>
        <appender-ref ref="WARN_FILE"/>
    </appender>

    <appender name="ASYNC_ERROR" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <includeCallerData>false</includeCallerData>
        <appender-ref ref="ERROR_FILE"/>
    </appender>

    <appender name="ASYNC_ALL" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>512</queueSize>
        <includeCallerData>false</includeCallerData>
        <appender-ref ref="ALL_FILE"/>
    </appender>

    <!-- 开发环境配置 -->
    <springProfile name="dev">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="ASYNC_ALL"/>
        </root>
    </springProfile>

    <!-- 测试环境配置 -->
    <springProfile name="test">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="ASYNC_INFO"/>
            <appender-ref ref="ASYNC_WARN"/>
            <appender-ref ref="ASYNC_ERROR"/>
        </root>
    </springProfile>

    <!-- 生产环境配置 -->
    <springProfile name="prod">
        <root level="INFO">
            <appender-ref ref="ASYNC_INFO"/>
            <appender-ref ref="ASYNC_WARN"/>
            <appender-ref ref="ASYNC_ERROR"/>
        </root>
    </springProfile>

    <!-- 默认配置 -->
    <springProfile name="default">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="ASYNC_ALL"/>
        </root>
    </springProfile>

    <!-- 应用特定包的日志级别 -->
    <logger name="com.sandwich.logtracing" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="ASYNC_ALL"/>
    </logger>

    <!-- Spring框架日志级别 -->
    <logger name="org.springframework" level="INFO"/>

    <!-- 数据库相关日志级别 -->
    <logger name="org.hibernate" level="WARN"/>
    <logger name="org.springframework.jdbc" level="INFO"/>

</configuration>

这个日志文件是用一个文件满足不同环境的配置的，根据不同的active profile自动匹配不同环境的日志输出配置。前面手写链路追踪我一直没有添加日志管理文件，都是用springboot系统默认的。

3.7 公共yml file改造(application.yml)

spring:
  application:
    name: log-tracing


# 日志配置
logging:
  level:
    com.sandwich.logtracing: DEBUG
    org.springframework: INFO
  pattern:
    console: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %X{traceId:-} %-5level %logger{50} - %msg%n"
    file: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %X{traceId:-} %-5level %logger{50} - %msg%n"
  file:
    name: ./logs/log-tracing.log
  logback:
    rollingpolicy:
      max-file-size: 100MB
      max-history: 30

这里的pattern是为了验证yml的配置优先级高还是xml的配置优先级更高。

yml的pattern如下：
"%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %X{traceId:-} %-5level %logger{50} - %msg%n"
xml的pattern如下：
"%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{traceId}] %-5level %logger{50} - %msg%n"

xml的trace id 配置[%X{traceId}]是我故意留有缺陷的，它会使得traceId为空的时候显示一个空括号[], 这不仅影响API请求日志

3.8 增加一个dev场的profile(application-dev.yml)

server:
  port: 8080

这个配置比较简单，只是为了验证active profile可以自动匹配对应的日志配置而新增的一个profile

4.测试验证

  • 用dev profile启动项目


  • 用shell client发送 API 请求

$ ./login.sh
Generated traceId from client side: A7Ua41KRLabtzUo
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   144    0   100  100    44    125     55 --:--:-- --:--:-- --:--:--   180
Response from login API:
{
    "responseCode": 200,
    "message": "success",
    "data": "Sandwich login success",
    "traceId": "A7Ua41KRLabtzUo"
}
  • 验证日志

由上图日志可以看出：

  • 1.用MDC的方式能保留多线程的不同线程名
  • 2.以上实现也能追踪异步线程
  • 3.trace id只影响了API请求的线程，并不影响[main]线程，[main]线程日志并没有因为trace id为空而出现[ ], 所以日志pattern生效的是yml里面的配置，它的优先级更高，能取代xml里面关于pattern的配置
  • 4.thread local里面的trace id在API异步线程的API主线程里面分别被removed了一遍，先removed了子线程的，再removed父线程的。保留线程名的好处在这个分析里面进一步体现了它的好处
  • 5.MDC中的trace id，可以在请求上下文中任何节点取出来，如本次API在response前直接get出来
  • 6.logback配置不同环境的配置，可以通过active profile自动匹配

5. 总结

本文用MDC的方式优化了手写链路追踪，MDC在日志上下文的使用非常方便灵活，你可以在java代码中对它进行get, set, 也可以把它读出来，通过xml/yml配置的日志管理方式把它写进日志里面。到目前为止，我们的链路追踪还只是集中在trace id, 后面我们继续研究它的其他妙用。如果您有好的建议，请在评论区与我分享。请关注我，我们下期继续。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
平台声明：文章内容（如有图片或视频亦包括在内）由作者上传并发布，文章内容仅代表作者本人观点，简书系信息发布平台，仅提供信息存储服务。

推荐阅读更多精彩内容