MDC实现链路追踪_mdc链路追踪-优快云博客

MDC链路追踪

解决：线上日志查看过慢

cat -n info.log |grep "a415ad50dbf84e99b1b56a31aacd209c"
grep -10 'a415ad50dbf84e99b1b56a31aacd209c' info.log   （10是指上下10行）

一、配置文件

1.1 application.yml增加

server:
  servlet:
    context-path: /zz
  port: 8999
logging:
  config: classpath:logback-spring.xml

1.2 logback-spring.xml文件

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
	<!--定义日志文件的存储地址 -->
	<property name="LOG_HOME" value="../logs" />

	<!--<property name="COLOR_PATTERN" value="%black(%contextName-) %red(%d{yyyy-MM-dd HH:mm:ss}) %green([%thread]) %highlight(%-5level) %boldMagenta( %replace(%caller{1}){'\t|Caller.{1}0|\r\n', ''})- %gray(%msg%xEx%n)" />-->
	<!-- 控制台输出 -->
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
			<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50}:%L - %msg%n</pattern>-->
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %X{TRACE_ID} [%thread] %highlight(%-5level) %cyan(%logger{50}:%L) - %msg%n</pattern>
		</encoder>
	</appender>

	<!-- 按照每天生成日志文件 -->
	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
			<!--日志文件输出的文件名 -->
			<FileNamePattern>${LOG_HOME}/sso-%d{yyyy-MM-dd}.%i.log</FileNamePattern>
			<!--日志文件保留天数 -->
			<MaxHistory>30</MaxHistory>
			<maxFileSize>10MB</maxFileSize>
		</rollingPolicy>
		<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
			<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符 -->
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %X{TRACE_ID} [%thread] %-5level %logger{50}:%L - %msg%n</pattern>
		</encoder>
	</appender>

	<!-- 生成 error html格式日志开始 -->
	<appender name="HTML" class="ch.qos.logback.core.FileAppender">
		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<!--设置日志级别,过滤掉info日志,只输入error日志-->
			<level>ERROR</level>
		</filter>
		<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
			<layout class="ch.qos.logback.classic.html.HTMLLayout">
				<pattern>%p%d%msg%M%F{32}%L</pattern>
			</layout>
		</encoder>
		<file>${LOG_HOME}/error-log.html</file>
	</appender>
	<!-- 生成 error html格式日志结束 -->

	<!-- 每天生成一个html格式的日志开始 -->
	<appender name="FILE_HTML" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
			<!--日志文件输出的文件名 -->
			<FileNamePattern>${LOG_HOME}/sso-%d{yyyy-MM-dd}.%i.html</FileNamePattern>
			<!--日志文件保留天数 -->
			<MaxHistory>30</MaxHistory>
			<MaxFileSize>10MB</MaxFileSize>
		</rollingPolicy>
		<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
			<layout class="ch.qos.logback.classic.html.HTMLLayout">
				<pattern>%p%d%msg%M%F{32}%L</pattern>
			</layout>
		</encoder>
	</appender>
	<!-- 每天生成一个html格式的日志结束 -->

	<!--myibatis log configure -->
	<logger name="com.apache.ibatis" level="TRACE" />
	<logger name="java.sql.Connection" level="DEBUG" />
	<logger name="java.sql.Statement" level="DEBUG" />
	<logger name="java.sql.PreparedStatement" level="DEBUG" />

	<!-- 日志输出级别 -->
	<root level="INFO">
		<appender-ref ref="STDOUT" />
		<appender-ref ref="FILE" />
		<appender-ref ref="HTML" />
		<appender-ref ref="FILE_HTML" />
	</root>

</configuration>

二、如何实现

采用得是拦截器方式，已每个线程为一个维度进行链路追踪
2.1 拦截器 WebMvcConfigurer添加拦截器

public class TraceInterceptor implements HandlerInterceptor {
    private static final String TRACE_ID = "TRACE_ID";
    /**
* MDC(Mapped Diagnostic Context)诊断上下文映射，是@Slf4j提供的一个支持动态打印日志信息的工具
* @param request
* @param response
* @param handler
* @return
*/
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        String tid = UUID.randomUUID().toString().replace("-", "");
        if (!StringUtils.isEmpty(request.getHeader("TRACE_ID"))) {
            tid = request.getHeader("TRACE_ID");
        }
        MDC.put(TRACE_ID, tid);
        return true;
    }

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


@Configuration
public class InterceptorConfig implements WebMvcConfigurer {
    @Bean
    public TraceInterceptor logInterceptor() {
        return new TraceInterceptor();
    }
    @Bean
    public SmsLimitationInterceptor getSmsLimitationInterceptor(){
        return new SmsLimitationInterceptor();
    }

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(getSmsLimitationInterceptor()).addPathPatterns("/**");
        registry.addInterceptor(logInterceptor()).addPathPatterns("/**");
    }

}

2.2 测试

    @PostMapping("doTest")
    public String doTest(@RequestParam("name") String name) throws InterruptedException {
        log.info("入参 name={}",name);
        testTrace();
        log.info("调用结束 name={}",name);
        return "Hello,"+name;
    }
    private void testTrace(){
        log.info("这是一行info日志");
        log.error("这是一行error日志");
        testTrace2();
    }
    private void testTrace2(){
        log.info("这也是一行info日志");

    }

三、多线程问题

使用多线程时，子线程无法进行链路追踪
将父线程的trackId传递下去给子线程

2023-07-22 10:53:26.442 3a164288b6aa43d8bc568b8fa5ca4bc2 [http-nio-8999-exec-7] INFO  com.steven.kz.shelf.controller.sso.DemoCon:88 - 主线程:1
2023-07-22 10:53:26.443 3a164288b6aa43d8bc568b8fa5ca4bc2 [http-nio-8999-exec-7] INFO  com.steven.kz.shelf.controller.sso.DemoCon:89 - 主线程:1
2023-07-22 10:53:26.443 3a164288b6aa43d8bc568b8fa5ca4bc2 [http-nio-8999-exec-7] INFO  com.steven.kz.shelf.controller.sso.DemoCon:90 - 主线程:1
2023-07-22 10:53:26.447  [demoExecutor-0] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:105 - 子线程 --start
2023-07-22 10:53:26.448  [demoExecutor-0] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:111 - 这是一行info日志
2023-07-22 10:53:26.448  [demoExecutor-0] ERROR c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:112 - 这是一行error日志
2023-07-22 10:53:26.448  [http-nio-8999-exec-7] INFO  com.steven.kz.shelf.config.filter.TokenFilter:66 - 无需鉴权已放行,url:/internal/external/doTestT
2023-07-22 10:53:26.449  [demoExecutor-0] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:116 - 这也是一行info日志
2023-07-22 10:53:26.449  [demoExecutor-0] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:107 - 子线程 --end

3.1 重写ThreadPoolTaskExecutor

public final class MyThreadPoolTaskExecutor  extends ThreadPoolTaskExecutor {
    public MyThreadPoolTaskExecutor() {
        super();
    }
    @Override
    public void execute(Runnable task) {
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }
    
    @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 final class ThreadMdcUtil {
    private static final String TRACE_ID = "TRACE_ID";
 
    // 获取唯一性标识
    public static String generateTraceId() {
        return UUID.randomUUID().toString();
    }
 
    public static void setTraceIdIfAbsent() {
        if (MDC.get(TRACE_ID) == null) {
            MDC.put(TRACE_ID, generateTraceId());
        }
    }
 
    /**
     * 用于父线程向线程池中提交任务时，将自身MDC中的数据复制给子线程
     *
     * @param callable
     * @param context
     * @param <T>
     * @return
     */
    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();
            }
        };
    }
 
    /**
     * 用于父线程向线程池中提交任务时，将自身MDC中的数据复制给子线程
     *
     * @param runnable
     * @param context
     * @return
     */
    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();
            }
        };
    }
}

一定要使用我们重写后得类去创建线程池

@Configuration
@EnableAsync
public class ThreadPoolConfig {
    @Bean("MyExecutor")
    public Executor asyncExecutorT() {
        MyThreadPoolTaskExecutor executor = new MyThreadPoolTaskExecutor();
        //核心线程数5：线程池创建时候初始化的线程数
        executor.setCorePoolSize(5);
        //最大线程数5：线程池最大的线程数，只有在缓冲队列满了之后才会申请超过核心线程数的线程
        executor.setMaxPoolSize(5);
        //缓冲队列500：用来缓冲执行任务的队列
        executor.setQueueCapacity(500);
        //允许线程的空闲时间60秒：当超过了核心线程出之外的线程在空闲时间到达之后会被销毁
        executor.setKeepAliveSeconds(60);
        //线程池名的前缀：设置好了之后可以方便我们定位处理任务所在的线程池
        executor.setThreadNamePrefix("asyncJCccc");
        executor.initialize();
        return executor;
    }
}

扩展
ThreadPoolTaskExecutor是Spring框架对ThreadPoolExecutor的封装，它继承自ThreadPoolExecutor类，并提供了更多的功能和灵活性。下面是ThreadPoolTaskExecutor和ThreadPoolExecutor之间的主要区别：

封装程度：ThreadPoolTaskExecutor是对ThreadPoolExecutor的封装，提供了更高级别的抽象，以便于在Spring框架中使用。它提供了各种配置选项和自定义扩展点，更易于使用和管理。
配置灵活性：ThreadPoolTaskExecutor提供了更多的配置选项和属性，例如核心线程数、最大线程数、队列容量、线程池名称等。这些配置可以通过Spring配置文件或注解进行灵活配置，而ThreadPoolExecutor需要手动编写代码进行配置。
监控和管理：ThreadPoolTaskExecutor提供了丰富的监控和管理功能。它集成了Spring的任务执行框架，可以与其他Spring特性（如异步执行、定时任务）无缝集成。同时，它还提供了一些便利的方法和钩子，可以用于任务执行状态的监控、错误处理和自定义行为。
依赖关系：ThreadPoolTaskExecutor是Spring框架的一部分，因此在使用Spring框架的项目中无需额外导入依赖。而ThreadPoolExecutor是Java标准库中的类，需要手动引入java.util.concurrent包。

总的来说，ThreadPoolTaskExecutor是对ThreadPoolExecutor的增强和封装，提供了更多的功能和灵活性。它是在Spring框架中使用线程池的推荐方式，特别适用于基于Spring的应用程序开发。而ThreadPoolExecutor是Java标准库提供的原生线程池实现，可以直接在任何Java项目中使用。

2023-07-22 11:24:02.397 5bb69626459e42c1b0f88a3965b1de4e [http-nio-8999-exec-1] INFO  com.steven.kz.shelf.controller.sso.DemoCon:88 - 主线程:1
2023-07-22 11:24:02.397 5bb69626459e42c1b0f88a3965b1de4e [http-nio-8999-exec-1] INFO  com.steven.kz.shelf.controller.sso.DemoCon:89 - 主线程:1
2023-07-22 11:24:02.397 5bb69626459e42c1b0f88a3965b1de4e [http-nio-8999-exec-1] INFO  com.steven.kz.shelf.controller.sso.DemoCon:90 - 主线程:1
2023-07-22 11:24:07.805 5bb69626459e42c1b0f88a3965b1de4e [asyncJCccc1] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:105 - 子线程 --start
2023-07-22 11:24:07.811 5bb69626459e42c1b0f88a3965b1de4e [asyncJCccc1] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:111 - 这是一行info日志
2023-07-22 11:24:07.811 5bb69626459e42c1b0f88a3965b1de4e [asyncJCccc1] ERROR c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:112 - 这是一行error日志
2023-07-22 11:24:07.811 5bb69626459e42c1b0f88a3965b1de4e [asyncJCccc1] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:116 - 这也是一行info日志
2023-07-22 11:24:07.815 5bb69626459e42c1b0f88a3965b1de4e [asyncJCccc1] INFO  c.steven.kz.shelf.sso.service.impl.SmsServiceImpl:107 - 子线程 --end

将trackId封装到返回值里，便于快速查看日志

{
  "traceId": "5f1b68bfe19b49ad86548ea1e7112b29",
  "code": "0",
  "msg": "success",
  "success": true,
  "data": "Hello,哇"
}