Java 日志链路追踪MDC 子线程 java 全链路追踪

转载

mob6454cc71d565 2023-09-25 15:50:03

文章标签 Java 日志链路追踪MDC 子线程 java 开发语言链路 ide 文章分类 Java 后端开发

什么是链路追踪？

链路追踪是一种针对分布式架构下实现请求链路可视化监控的一种技术。
它的核心目的就是去了解分布式系统中的请求调用行为，从而从整体到局部详细展示各项系统指标。
实现故障的快速定位，缩短故障排除的时间。

常用的链路追踪工具

Zipkin、Skywalking、Cat、Pinpoint。

对于一些规模较大的分布式系统，一个用户的请求，可能需要涉及到多个子系统的流转（如图）。

Java 日志链路追踪MDC 子线程 java 全链路追踪_java

而且随着业务的不断增长，服务之间的调用关系也会越来越复杂。
在这样一个背景下，我们一方面需要去了解整个请求链路的调用关系，去定位到性能问题另一方面还需要从整体到局部展示各项系统指标，快速实现故障定位和回复。所以产生了链路追踪的需求。

最早的链路监控系统是Google的Dapper，在2010年的时候Google发布了一篇论文介绍Dapper的整体设计。
目前市面上所有的链路监控系统都是在它的理论模型下衍生出来的。
包括阿里的鹰眼、大众点评的cat、Twitter的Zipkin等等

解决什么问题

有了全链路监控工具，解决以下几个方面的问题：
请求链路追踪，故障快速定位：可以通过调用链结合业务日志快速定位错误信息。

可视化：各个阶段耗时，进行性能分析。
依赖优化：各个调用环节的可用性、梳理服务依赖关系以及优化。
数据分析，优化链路：可以得到用户的行为路径，汇总分析应用在很多业务场景。

全链路日志追踪traceId(http、dubbo、mq)

目的
目前许多系统项目之间的调用，有基于微服务的，有通过HTTP请求的，还有通过mq的。那么在处理一次请求的时候，可能会调用多个服务或者调用多个其他系统功能，这样就会产生很多的日志，此时，如果想查看这一次调用的完整的请求链路的日志时，就会变得比较困难，虽然我们有一些集中的日志收集工具比如ELK，我们需要把这一些日志串联起来，这个问题很关键，因为如果没有串联起来，排查日志就是一件很困难的事情。
解决办法
一般来说，系统之间的调用不外乎两种：http和dubbo。当然还有通过中间件mq的形式（SpringCloud也是基于MVC容器调用），系统内部有task定时任务等。

对于http请求：我们的做法是在最开始请求系统时候生成一个全局唯一的TraceID，放在http 请求header中，系统接收到请求后，从header中取出这个TraceID，放入MDC中，这个TraceID伴随着这整个请求的调用周期，即当一个服务调用另外一个服务的时候，需要往下传递，从而形成一条链路，这样当我们查看日志时，只需要根据关键搜索这个TraceID，整条调用链路的日志都可以查出来。
对于dubbo请求：我们可以在最开始请求的时候生成一个全局唯一性TraceID，放入RpcContext中，但是有这么一个问题，RpcContext只能做到消费者和提供者共享同一个RpcContext，假设我有一种调用关系，serverA -> serverB -> serverC，A->B的时候可以获取相同内容的RpcContext，但是B->C时候，A和C就无法共享相同内容的RpcContext了，对于这种情况我们利用ThreadLocal进行解决，我们先从RpcContext取出TraceID，放入ThreadLocal中，当调用别的服务再放入RpcContext中即可。当然利用MDC可以实现。
对于系统内部的task任务：同样在每个task开始执行之前系统内部生成一个全局唯一TraceID，然后把TraceID放入MDC中。
对于mq：与上面相同，在每个MQ listener处理数据开始之前调用一个共公方法生成一个全局唯一TraceID，然后把TraceID放入MDC中。

经过这些处理之后，我们在打印日志的时候只需要从MDC取出TraceID打印出来即可。

适用范围
语言环境：Java
项目架构：SSM项目。SpringBoot项目，dubbo服务，SpringCloud微服务
日志框架：log4j，logback

在Java项目中使用traceId跟踪请求全流程日志

最近在项目开发中遇到了一些问题，项目为多机部署，使用kibana收集日志，但并发大时使用日志定位比较麻烦，大量日志输出导致很难筛出指定请求的全部相关日志，以及下游服务调用对应的日志。因此计划对项目日志打印进行一些小改造，使用一个traceId跟踪请求的全部路径，前提是不修改原有的打印方式。

简单的解决思路
想要跟踪请求，第一个想到的就是当请求来时生成一个traceId放在ThreadLocal里，然后打印时去取就行了。但在不改动原有输出语句的前提下自然需要日志框架的支持了，搜索的一番发现主流日志框架都提供了MDC功能。

MDC
MDC 介绍 MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的Map，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。

简而言之，MDC就是日志框架提供的一个InheritableThreadLocal，项目代码中可以将键值对放入其中，然后使用指定方式取出打印即可。

在 log4j 和 logback 的取值方式为：

%X{traceid}

初步实现
首先创建拦截器，加入拦截列表中，在请求到达时生成traceId。当然你还可以根据需求在此处后或后续流程中放入spanId、订单流水号等需要打印的信息。

public class Constants {

    /**
     * 日志跟踪id名。
     */
    public static final String LOG_TRACE_ID = "traceid";

    /**
     * 请求头跟踪id名。
     */
    public static final String HTTP_HEADER_TRACE_ID = "app_trace_id";
}

import org.slf4j.MDC;

public class TraceInterceptor extends HandlerInterceptorAdapter {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        // "traceId"
        MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
        return true;
    }
}

然后在日志配置xml文件中添加traceId打印：

<property name="normal-pattern" value="[%p][%d{yyyy-MM-dd'T'HH:mm:ss.SSSZ,Asia/Shanghai}][%X{traceid}][%15.15t][%c:%L] %ms

初步改造完成！是不是感觉还挺简单的？且慢，仅仅这样的改造在实际使用过程中会遇到以下问题：

线程池中的线程会打印错误的traceId
调用下游服务后会生成新的traceId，无法继续跟踪下面来一一解决这些问题。
支持线程池跟踪
MDC使用的InheritableThreadLocal只是在线程被创建时继承，但是线程池中的线程是复用的，后续请求使用已有的线程将打印出之前请求的traceId。这时候就需要对线程池进行一定的包装，在线程在执行时读取之前保存的MDC内容。不仅自身业务会用到线程池，spring项目也使用到了很多线程池，比如@Async异步调用，zookeeper线程池、kafka线程池等。不管是哪种线程池都大都支持传入指定的线程池实现，拿@Async举例：

@Bean("SpExecutor")
public Executor getAsyncExecutor() {
    // 对线程池进行包装，使之支持traceId透传
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor() {
        @Override
        public <T> Future<T> submit(Callable<T> task) {
            // 传入线程池之前先复制当前线程的MDC
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
        @Override
        public void execute(Runnable task) {
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
    };
    executor.setCorePoolSize(config.getPoolCoreSize());
    ... // 其他配置
    executor.initialize();
    return executor;
}

public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
    return new Callable<T>() {
        @Override
        public T call() throws Exception {
            // 实际执行前导入对应请求的MDC副本
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            if (MDC.get(Constants.LOG_TRACE_ID) == null) {
                MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
            }
            try {
                return callable.call();
            } finally {
                MDC.clear();
            }
        }
    };
}

ThreadPoolExecutor的包装也类似，注意为了严谨考虑，需要对连接池中的所有调用方法进行封装。

在ThreadPoolExecutor中有：

public void execute(Runnable command)
public <T> Future<T> submit(Callable<T> task)
public Future<?> submit(Runnable task)
public <T> Future<T> submit(Runnable task, T result)

在ThreadPoolTaskExecutor中有：

public void execute(Runnable command)
public void execute(Runnable task, long startTimeout)
public Future<?> submit(Runnable task)
public <T> Future<T> submit(Runnable task, T result)
public <T> ListenableFuture<T> submitListenable(Callable<T> task)
public ListenableFuture<?> submitListenable(Runnable task)

方式与上述的实现类似，不做赘述。提供一下我的工具类：

public class ThreadMdcUtil {

    public static void setTraceIdIfAbsent() {
        if (MDC.get(Constants.LOG_TRACE_ID) == null) {
            MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
        }
    }

    public static void setTraceId() {
        MDC.put(Constants.LOG_TRACE_ID, TraceLogUtils.getTraceId());
    }

    public static void setTraceId(String traceId) {
        MDC.put(Constants.LOG_TRACE_ID, traceId);
    }

    public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            setTraceIdIfAbsent();
            try {
                return callable.call();
            } finally {
                MDC.clear();
            }
        };
    }

    public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            setTraceIdIfAbsent();
            try {
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }

    public static class ThreadPoolTaskExecutorMdcWrapper extends ThreadPoolTaskExecutor {
        @Override
        public void execute(Runnable task) {
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public void execute(Runnable task, long startTimeout) {
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);
        }

        @Override
        public <T> Future<T> submit(Callable<T> task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public Future<?> submit(Runnable task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public ListenableFuture<?> submitListenable(Runnable task) {
            return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public <T> ListenableFuture<T> submitListenable(Callable<T> task) {
            return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
    }

    public static class ThreadPoolExecutorMdcWrapper extends ThreadPoolExecutor {
        public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                            BlockingQueue<Runnable> workQueue) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
        }

        public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                            BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
        }

        public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                            BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
        }

        public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                            BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,
                                            RejectedExecutionHandler handler) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
        }

        @Override
        public void execute(Runnable task) {
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public <T> Future<T> submit(Runnable task, T result) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
        }

        @Override
        public <T> Future<T> submit(Callable<T> task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public Future<?> submit(Runnable task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
    }

    public static class ForkJoinPoolMdcWrapper extends ForkJoinPool {
        public ForkJoinPoolMdcWrapper() {
            super();
        }

        public ForkJoinPoolMdcWrapper(int parallelism) {
            super(parallelism);
        }

        public ForkJoinPoolMdcWrapper(int parallelism, ForkJoinWorkerThreadFactory factory,
                                      Thread.UncaughtExceptionHandler handler, boolean asyncMode) {
            super(parallelism, factory, handler, asyncMode);
        }

        @Override
        public void execute(Runnable task) {
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public <T> ForkJoinTask<T> submit(Runnable task, T result) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
        }

        @Override
        public <T> ForkJoinTask<T> submit(Callable<T> task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
    }
}

下游服务使用相同traceId
以上方式在多级服务调用中每个服务都会生成新的traceId，导致无法衔接跟踪。这时就需要对http调用工具进行相应的改造了，在发送http请求时自动将traceId添加到header中，以RestTemplate为例，注册拦截器：

/ 以下省略其他相关配置
RestTemplate restTemplate = new RestTemplate();
// 使用拦截器包装http header
restTemplate.setInterceptors(new ArrayList<ClientHttpRequestInterceptor>() {
    {
        add((request, body, execution) -> {
            String traceId = MDC.get(Constants.LOG_TRACE_ID);
            if (StringUtils.isNotEmpty(traceId)) {
                request.getHeaders().add(Constants.HTTP_HEADER_TRACE_ID, traceId);
            }
            return execution.execute(request, body);
        });
    }
});

HttpComponentsClientHttpRequestFactory factory = new HttpComponentsClientHttpRequestFactory();
// 注意此处需开启缓存，否则会报getBodyInternal方法“getBody not supported”错误
factory.setBufferRequestBody(true);
restTemplate.setRequestFactory(factory);

下游服务的拦截器改为：

public class TraceInterceptor extends HandlerInterceptorAdapter {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        String traceId = request.getHeader(Constants.HTTP_HEADER_TRACE_ID);
        if (StringUtils.isEmpty(traceId)) {
            traceId = TraceLogUtils.getTraceId();
        }
        MDC.put(Constants.LOG_TRACE_ID, traceId);
        return true;
    }
}

若使用自定义的http客户端，则直接修改其工具类即可。

针对其他协议的调用暂无实践经验，可以借鉴上面的思路，通过拦截器插入特定字段，再在下游读取指定字段加入MDC中。

总结
实现日志跟踪的基本方案没有太大难度，重在实践中发现问题并一层一层解决问题的思路。

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。

下一篇：java url替换参数 java中替换

提问和评论都可以，用心的回复会被更多人看到评论

发布评论

相关文章

官方博客	全部文章	热门标签	班级博客
了解我们	网站地图	意见反馈

鸿蒙开发者社区	51CTO学堂
51CTO	软考资讯