Java单体架构链路追踪实践

1. 概述

最近心血来潮，打算研究一下链路追踪，说白了就是系统中的一个TraceID，TraceID是一个唯一标识符，用来标识一次完整的请求调用。当用户发起一个请求时，系统会生成一个TraceID，这个请求在经过各个服务、组件时都会携带这个TraceID，形成一条完整的调用链。

2. 主要作用

问题排查：当系统出现问题时，可以通过TraceID快速定位到具体的请求链路，查看每个环节的执行情况。

性能监控：追踪请求在各个服务中的耗时，找出性能瓶颈。

依赖关系分析：了解服务间的调用关系和依赖情况。

3. 实践步骤

  1. 在logback.xml中添加%X{traceId}。

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{traceId}] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

  2. 编写TraceContext类，此类用于存储和管理跟踪信息。

    public class TraceContextUtils {
    private static final ThreadLocal<TraceInfo> TRACE_INFO = new ThreadLocal<>();

    public static class TraceInfo {
        /**
         * 请求的唯一标识符
         */
        private final String traceId;

        /**
         * 请求开始时间
         */
        private final long startTime;

        /**
         * 请求的URI
         */
        private final String requestUri;

        public TraceInfo(String traceId, String requestUri) {
            this.traceId = traceId;
            this.startTime = System.currentTimeMillis();
            this.requestUri = requestUri;
        }

        public String getTraceId() {
            return traceId;
        }

        public long getStartTime() {
            return startTime;
        }

        public String getRequestUri() {
            return requestUri;
        }

        /**
         * 获取请求的持续时间
         *
         * @return 持续时间，单位为毫秒
         */
        public long getDuration() {
            return System.currentTimeMillis() - startTime;
        }
    }

    public static void setTraceInfo(String traceId, String requestUri) {
        TRACE_INFO.set(new TraceInfo(traceId, requestUri));
    }

    public static TraceInfo getTraceInfo() {
        return TRACE_INFO.get();
    }

    public static String getTraceId() {
        TraceInfo info = TRACE_INFO.get();
        return info != null ? info.getTraceId() : null;
    }

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

  3. 编写一个过滤器，每次请求过来的时候生成TraceID，让后将TraceID放入请求头同时放入ThreadLocal中记录下TraceID。

    @Component
@Order(1) //自定义过滤器的执行顺序
public class TraceFilter implements Filter {

    private static final Logger log = LoggerFactory.getLogger(TraceFilter.class);

    @Override
    public void doFilter(ServletRequest request, ServletResponse response,
                         FilterChain chain) throws IOException, ServletException {

        HttpServletRequest httpRequest = (HttpServletRequest) request;
        HttpServletResponse httpResponse = (HttpServletResponse) response;

        // 生成TraceID
        String traceId = generateTraceId();

        // 设置到ThreadLocal
        TraceContextUtils.setTraceInfo(traceId, httpRequest.getRequestURI());

        // 同时设置到MDC，这样日志就能自动输出TraceID
        MDC.put("traceId", traceId);

        // 添加到响应头
        httpResponse.setHeader("IKBM-Trace-ID", traceId);

        String requestUri = httpRequest.getRequestURI();
        log.info("请求开始 - URI: {}, Method: {}", requestUri, httpRequest.getMethod());

        try {
            chain.doFilter(request, response);
        } finally {
            log.info("请求结束 - URI: {}, 耗时: {}ms", requestUri, TraceContextUtils.getTraceInfo().getDuration());

            // 清理ThreadLocal和MDC
            TraceContextUtils.clear();
            MDC.clear();
        }
    }

    private String generateTraceId() {
        return UUID.randomUUID().toString().replace("-", "");
    }
}

    这里的MDC(org.slf4j.MDC)是门面日志框架slf4j中的上下文对象，保存了每次请求（一个线程）的日志打印相关信息（日期请求的requestId时间、日志内容等）。我们将每个请求生成的TraceID保存到MDC中即可实现在整个请求的过程中，打印的日志信息都可以带上同一TraceID。

现在咋们发送请求来验证一下：

请求头中的TraceID

现在我们根据这个TraceID来查询日志：

日志查询与链路观察

可见能够快速的查询到日志同时能够清楚的知道接口中的的调用流程。

因为我们的TraceID是存放到ThreadLocal中的，我们知道，每个线程他们的ThreadLocal中的内容都是独立的，那么多线程，如何保证TraceID的顺延呢？也就是说当请求发送的时候，当执行多线程的代码的时候，能否保证TraceID一致呢？

这就需要我们配置线程池了，我原本有线程池定义代码：

@Configuration
public class SpringConfig {

    @Bean(name = "ikbManageTaskExecutor")
    public TaskExecutor queueAsyncTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(8);
        executor.setMaxPoolSize(16);
        executor.setQueueCapacity(100);
        executor.setKeepAliveSeconds(60);
        executor.setThreadNamePrefix("ikb-manage-executor-");
        //保证在线程池与阻塞队列堆满的情况下把任务丢到主线程执行，保证任务不丢失
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        executor.setWaitForTasksToCompleteOnShutdown(true);
        //允许核心线程池超时
        executor.setAllowCoreThreadTimeOut(true);

        return executor;
    }
}

我们可以给线程池定义一个任务装饰类，这样，在真正异步任务执行的时候，可以在任务的前后执行TraceID获取和清理工作：

// 用于装饰任务的类，主要用于跟踪任务执行
public class TraceableTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        //获取主线程的TraceID以及requestUri
        String traceId = TraceContextUtils.getTraceId();
        String requestUri = TraceContextUtils.getTraceInfo().getRequestUri();
        return () -> {
            try {
                //将TraceID应用于新的线程
                TraceContextUtils.setTraceInfo(traceId, requestUri);
                MDC.put("traceId", traceId);
                runnable.run();
            } finally {
                //清理TraceID
                TraceContextUtils.clear();
                MDC.clear();
            }
        };
    }
}

之后，我们在线程池定义处给线程池指定任务装饰器：

设置线程池的任务装饰器

现在我们来发送一个请求，该请求中会启动异步任务：

请求TraceID

多线程TraceID观察

可见异步任务也是相同的TraceID。