穿梭线程的日志协奏曲：优雅地管理 Java 多线程日志追踪

写作原由

昨天解决现场问题，看了一眼目前项目打印的日志，本来主线程使用的相同的线程名称，结果到了子线程就彻底傻眼了，根本无法查看日志，也根本无法判断哪个子线程是给哪个主线程使用，再看了一眼，我们项目目前涉及到日志工具类，想了想还是自己梭哈一把。

引言

在微服务和分布式系统中，日志追踪是确保高可用性和故障排除的关键。随着系统的复杂性增加，跨服务甚至跨线程的日志关联变得至关重要。本文将介绍如何在Java多线程环境中保持日志的 traceId 一致性，以便能够追踪整个请求链路的日志输出。

日志追踪的挑战

在并发编程中，一个主线程可能会派生出多个子线程来处理任务。如果每个线程都有自己的日志输出，而没有一个统一的追踪标识符，那么在日志中追踪一个完整的操作流程将变得非常困难。traceId 作为一个唯一的标识符，可以帮助项目将分散在不同线程中的日志条目串联起来，形成一个连贯的故事线。

解决方案：LoggingUtil 和 TraceIdDecorator

为了解决跨线程的日志追踪问题，提出了两个工具类：LoggingUtil 和 TraceIdDecorator。这两个工具类的目标是简化 traceId 的管理，并确保它在父线程和子线程间的一致性。

日志公共模式定义

/**
 * @Author derek_smart
 * @Date 2024/7/4 8:00
 * @Description  日志模式接口定义
 */
public interface LogModule {

    String getModuleMsg();

    String getSubModuleMsg();

    String getSubModule();
}

LoggingUtil 的设计

LoggingUtil 是一个提供日志相关功能的工具类。它使用 InheritableThreadLocal 和 MDC（Mapped Diagnostic Context）来存储和传递 traceId。LoggingUtil也提供了一个静态方法 createModuleFormat，用于生成含有 traceId 和模块信息的格式化日志消息。

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

import java.util.concurrent.Callable;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Future;
/**
 * @Author derek_smart
 * @Date 2024/7/4 8:00
 * @Description  日志工具类
 */
public class LoggingUtil {

    private static final InheritableThreadLocal<String> traceIdThreadLocal = new InheritableThreadLocal<>();
    private static final String TRACE_ID_KEY = "traceId";

    // Set the traceId for the current thread
    public static void setTraceId(String traceId) {
        traceIdThreadLocal.set(traceId);
        MDC.put(TRACE_ID_KEY, traceId); // Set traceId in MDC
    }

    // Get the traceId for the current thread
    public static String getTraceId() {
        return traceIdThreadLocal.get();
    }

    // Clear the traceId for the current thread
    public static void clear() {
        traceIdThreadLocal.remove();
        MDC.remove(TRACE_ID_KEY); // Clear traceId from MDC
    }

    // Submit a task with inherited traceId
    public static <T> Future<T> submitWithTraceId(ExecutorService executorService,Callable<T> task) {
        final String parentTraceId = getTraceId();

        Callable<T> wrappedTask = () -> {
            try {
                setTraceId(parentTraceId);
                return task.call();
            } finally {
                clear();
            }
        };
        return executorService.submit(wrappedTask);
    }

    // Create a formatted log message with traceId and module information
    public static String createModuleFormat(LogModule module, String format) {
        String traceId = getTraceId();
        String threadName = Thread.currentThread().getName();
        String msg = StringUtils.isBlank(traceId) ?
                String.format("【%s】【%s】【%s】", module.getModuleMsg(), module.getSubModule(), module.getSubModuleMsg()) :
                String.format("TRACEID-【%s】【%s】:【%s】【%s】【%s】", traceId, threadName, module.getModuleMsg(), module.getSubModule(), module.getSubModuleMsg());
        return msg + format;
    }

    // Helper method to get a Logger instance
    public static Logger getLogger(Class<?> clazz) {
        return LoggerFactory.getLogger(clazz);
    }

    public static void debug(Logger logger, LogModule module, String format, Object... arguments) {
        logger.debug(createModuleFormat(module, format), arguments);
    }

    /**
     * 打印正常级别日志
     *
     * @param logger    日志对象
     * @param module    日志功能模块
     * @param format    格式化消息文本
     * @param arguments 参数
     */
    public static void info(Logger logger, LogModule module, String format, Object... arguments) {
        logger.info(createModuleFormat(module, format), arguments);
    }

}

LoggingUtil 是一个封装了日志记录和 traceId 管理功能的工具类。它的设计旨在简化跨线程日志记录的复杂性，并提供一致的 traceId 追踪。下面详细介绍其实现原理及优缺点。

实现原理

1. traceId 管理:

   • 使用 InheritableThreadLocal 保持 traceId 的跨线程一致性。InheritableThreadLocal 是 ThreadLocal 的一个变体，允许子线程继承父线程的本地变量值。
   • 结合 SLF4J 的 MDC（Mapped Diagnostic Context）功能，可以在日志记录时将 traceId 添加到每条日志消息中。MDC 是一个线程安全的存储区域，可以存储每个线程的上下文数据，并在记录日志时自动使用这些数据。

2. 日志记录器获取:

   • 通过 LoggerFactory.getLogger(clazz) 方法获取 SLF4J 的 Logger 实例，这样可以为每个类提供一个日志记录器。

3. 格式化日志消息:

   • createModuleFormat 方法用于生成包含 traceId、线程名称和模块信息的日志消息。这个方法根据是否存在 traceId 来决定消息的格式。

4. 日志记录方法:

   • 提供一系列日志记录方法（如 debug, info, warn, error），这些方法内部调用 createModuleFormat 来构建消息，并通过传入的 Logger 实例记录日志。

优点

• 跨线程追踪: LoggingUtil 通过 InheritableThreadLocal 和 MDC 的结合使用，使得在多线程环境中可以轻松追踪 traceId。
• 日志格式一致性: 可以统一日志格式，使得所有日志记录都包含必要的上下文信息，如 traceId 和模块信息。
• 简化日志记录: 开发者不需要在每次记录日志时手动添加 traceId 和模块信息，LoggingUtil 提供的方法自动处理这些操作。
• 易于集成和使用: 可以轻松集成到现有项目中，使用简单的 API 记录日志。

缺点

• 性能开销: InheritableThreadLocal 可能会引入额外的性能开销，尤其是在创建大量短生命周期的子线程时。
• 内存泄漏风险: 如果不正确管理 InheritableThreadLocal，可能会导致内存泄漏。例如，如果线程被重用（如线程池中的线程），而 traceId 没有被及时清除，那么可能会保留旧的 traceId 值。
• 日志库依赖: LoggingUtil 依赖于 SLF4J API，如果项目中使用的是其他日志框架，则需要适配或替换。
• 线程池兼容性: 默认的 InheritableThreadLocal 与线程池不总是兼容的，因为线程池中的线程通常会被重用，这可能需要额外的封装或自定义线程工厂来解决。

时序图：

这个时序图说明了以下步骤：

1. 客户端代码通过 LoggingUtil 设置 traceId。
2. LoggingUtil 将 traceId 存储在 MDC 中。
3. 客户端请求 LoggingUtil 获取一个 Logger 实例。
4. LoggingUtil 创建或获取一个 Logger 实例。
5. 客户端调用 LoggingUtil 的日志记录方法（如 debug, info, warn, error），传入 Logger 实例、日志模块信息、消息模板和参数。
6. LoggingUtil 调用 createModuleFormat 方法来生成格式化后的日志消息，包括 traceId 和模块信息。
7. LoggingUtil 通过 Logger 实例记录格式化后的日志消息。
8. 客户端代码完成日志记录后，通过 LoggingUtil 清除 traceId。
9. LoggingUtil 从 MDC 中移除 traceId。

TraceIdDecorator 的实现

TraceIdDecorator 则是一个更为通用的解决方案，它提供了一个装饰器方法 withTraceId，用于包装 Callable 任务。这个装饰器确保了 traceId 能够从父线程传递到子线程，并在任务执行完毕后清除。

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

import java.util.UUID;
import java.util.concurrent.Callable;
/**
 * @Author derek_smart
 * @Date 2024/7/4 8:00
 * @Description  TraceId装饰器
 */
public class TraceIdDecorator {

    private static final InheritableThreadLocal<String> traceIdThreadLocal = new InheritableThreadLocal<>();
    private static final String TRACE_ID_KEY = "traceId";
    /**
     * 生成一个唯一的 traceId。
     * @return 返回生成的 traceId 字符串。
     */
    public static String generateTraceId() {
        return UUID.randomUUID().toString().replaceAll("-", "");
    }
    public static void setTraceId(String traceId) {
        traceIdThreadLocal.set(traceId);
        MDC.put(TRACE_ID_KEY, traceId); // Set traceId in MDC
    }

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

    public static void clear() {
        traceIdThreadLocal.remove();
        MDC.remove(TRACE_ID_KEY); // Clear traceId from MDC
    }

    // Wrap a callable with traceId inheritance
    public static <T> Callable<T> withTraceId(Callable<T> task) {
        final String parentTraceId = getTraceId();

        return () -> {
            try {
                setTraceId(parentTraceId);
                return task.call();
            } finally {
                clear();
            }
        };
    }

    // Create a formatted log message with traceId and module information
    public static String createModuleFormat(LogModule module, String format) {
        String traceId = getTraceId();
        String threadName = Thread.currentThread().getName();
        String msg = StringUtils.isBlank(traceId) ?
                String.format("【%s】【%s】【%s】", module.getModuleMsg(), module.getSubModule(), module.getSubModuleMsg()) :
                String.format("TRACEID-【%s】【%s】:【%s】【%s】【%s】", traceId, threadName, module.getModuleMsg(), module.getSubModule(), module.getSubModuleMsg());
        return msg + format;
    }

    // Helper method to get a Logger instance
    public static Logger getLogger(Class<?> clazz) {
        return LoggerFactory.getLogger(clazz);
    }

    public static void debug(Logger logger, LogModule module, String format, Object... arguments) {
        logger.debug(createModuleFormat(module, format), arguments);
    }

    /**
     * 打印正常级别日志
     *
     * @param logger    日志对象
     * @param module    日志功能模块
     * @param format    格式化消息文本
     * @param arguments 参数
     */
    public static void info(Logger logger, LogModule module, String format, Object... arguments) {
        logger.info(createModuleFormat(module, format), arguments);
    }
}

实现原理

1. InheritableThreadLocal:

   • InheritableThreadLocal 是 ThreadLocal 的一个变体，它允许子线程从创建它们的父线程那里继承值。TraceIdDecorator 使用 InheritableThreadLocal 来存储 traceId，以便在多线程环境中跨线程保持 traceId 的一致性。

2. SLF4J MDC:

   • MDC 是 SLF4J 提供的一种机制，允许开发者在日志消息中包含关键的上下文信息。TraceIdDecorator 通过 MDC.put 方法将 traceId 存储在 MDC 中，这样每条日志消息都会自动包含 traceId。

3. 任务包装:

   • withTraceId 方法接受一个 Callable 对象，并返回一个新的 Callable 对象。这个新的 Callable 对象在被调用时，会先设置 traceId，然后执行原始任务，最后清除 traceId。

4. 日志格式化:

   • createModuleFormat 方法负责生成包含 traceId、线程名称和模块信息的格式化日志消息。这样做可以确保日志消息具有足够的上下文信息，便于追踪和调试。

优点

• 跨线程追踪: TraceIdDecorator 使得在多线程环境中跟踪操作变得简单，因为它确保 traceId 在父线程和子线程之间保持一致。
• 日志一致性: 通过自动在每条日志消息中包含 traceId，TraceIdDecorator 帮助创建了一致的日志格式，这对于后续的日志分析和问题解决非常有用。
• 易于集成和使用: TraceIdDecorator 提供了易于使用的静态方法，开发者可以很容易地将其集成到现有的多线程应用程序中。
• 清晰的日志上下文: 通过包含模块信息和 traceId，TraceIdDecorator 增加了日志消息的上下文清晰度，有助于快速定位问题。

缺点

• 性能考虑: InheritableThreadLocal 可能会在高并发场景下引入性能开销，因为它需要在创建新线程时复制父线程的值。
• 内存泄漏风险: 如果线程被重用（如在线程池中），那么 InheritableThreadLocal 可能会导致内存泄漏，因为线程的 traceId 值可能不会被及时清除。
• 线程池兼容性: InheritableThreadLocal 与线程池的兼容性可能是一个问题，因为线程池中的线程通常会被重用。这可能需要开发者实施额外的策略，如使用自定义线程工厂。
• 依赖特定的日志框架: TraceIdDecorator 依赖于 SLF4J 和 MDC，如果项目使用的是其他日志框架，则需要适配或替换。

时序图：

时序图步骤：

1. 主线程设置 traceId，并通过 TraceIdDecorator 将其存储在 MDC 中。
2. 主线程记录开始处理的信息。
3. 主线程向线程池提交子线程任务，使用 TraceIdDecorator.withTraceId 方法包装任务，确保 traceId 能够被子线程继承。
4. 子线程开始执行，TraceIdDecorator 在子线程中设置相同的 traceId。
5. 子线程记录开始处理的信息，执行业务逻辑，然后记录处理完成的信息。
6. 子线程完成后，TraceIdDecorator 清除子线程的 traceId。
7. 主线程完成处理，TraceIdDecorator 清除主线程的 traceId。

业务方的灵活性

TraceIdDecorator 的设计允许业务方保持对线程池的完全控制。业务方可以根据自己的需求来创建和管理线程池，同时使用 TraceIdDecorator 来确保 traceId 的一致性。

实战演练

文章接下来将通过代码示例展示如何使用 LoggingUtil 和 TraceIdDecorator。我们将演示如何在主线程中设置 traceId，如何使用装饰器来传递 traceId，以及如何在业务逻辑中灵活地使用自定义的线程池。

LoggingUtil 实战示例

import org.slf4j.Logger;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;

public class Application {
    private static final Logger logger = LoggingUtil.getLogger(Application.class);

    public static void main(String[] args) {
        // 设置trace ID
        String traceId = "1234567890";
        LoggingUtil.setTraceId(traceId);
        
        // 记录带有trace ID的信息日志
        LoggingUtil.info(logger, BaseLogModule.APPLICATION, "Application is starting...");

        // 创建线程池
        ExecutorService executorService = Executors.newFixedThreadPool(2);

        // 提交任务，同时继承trace ID
        Future<?> future = LoggingUtil.submitWithTraceId(executorService, () -> {
            // 在这个任务中，trace ID会被继承
            LoggingUtil.info(logger, BaseLogModule.APPLICATION, "Task is running...");
            return null;
        });

        // 其他业务逻辑...
        
        // 清理trace ID
        LoggingUtil.clear();

        // 关闭线程池
        executorService.shutdown();
    }
}

enum BaseLogModule implements LogModule {
    APPLICATION("Application", "Main", "Application related logs"),
    DATABASE("Database", "DB", "Database operation logs");

    private final String moduleMsg;
    private final String subModule;
    private final String subModuleMsg;

    LogModule(String moduleMsg, String subModule, String subModuleMsg) {
        this.moduleMsg = moduleMsg;
        this.subModule = subModule;
        this.subModuleMsg = subModuleMsg;
    }

    public String getModuleMsg() {
        return moduleMsg;
    }

    public String getSubModule() {
        return subModule;
    }

    public String getSubModuleMsg() {
        return subModuleMsg;
    }
}

LoggingUtil使用对业务侵入性过强，使业务方多线程调用必须使用 LoggingUtil.submitWithTraceId进行启动。 故此建议使用下面TraceIdDecorator。

TraceIdDecorator 实战示例

import org.slf4j.Logger;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Callable;

public class ParentChildThreadLoggingExample {

    private static final Logger logger = TraceIdDecorator.getLogger(ParentChildThreadLoggingExample.class);

    public static void main(String[] args) {
        // 在主线程（父线程）设置 traceId
        String traceId = UUID.randomUUID().toString();
      TraceIdDecorator.setTraceId(traceId);

        // 创建日志模块信息
        LogModule mainModule = new LogModule("ParentChildThreadLoggingExample", "Main", "Starting main thread");

        // 记录父线程开始的日志
        TraceIdDecorator.info(logger, mainModule, "Main thread started with traceId: {}", traceId);

        // 创建一个线程池来执行子线程任务
        ExecutorService executorService = Executors.newFixedThreadPool(2);

        // 创建并提交一个子线程任务
        Callable<Void> childTask = () -> {
            // 创建子线程的日志模块信息
            LogModule childModule = new LogModule("ParentChildThreadLoggingExample", "ChildTask", "Starting child task");

            // 记录子线程开始的日志
            TraceIdDecorator.info(logger, childModule, "Child task started with inherited traceId: {}", TraceIdDecorator.getTraceId());

            // 执行子线程的业务逻辑...
            // ...

            // 记录子线程完成的日志
            TraceIdDecorator.info(logger, childModule, "Child task completed with inherited traceId: {}", TraceIdDecorator.getTraceId());
			    return null;
        };

        // 使用 TraceIdDecorator 的 withTraceId 方法来确保子线程继承 traceId
        executorService.submit(TraceIdDecorator.withTraceId(childTask));

        // 清理父线程的 traceId  
		TraceIdDecorator.clear();

        // 关闭线程池
        executorService.shutdown();
    }
}

TraceIdDecorator进一步优化

这样写 有点丑陋 ，可以定义一个切面

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.concurrent.Callable;
/**
 * @Author derek_smart
 * @Date 2024/7/4 8:00
 * @Description  TraceId切面
 */
@Aspect
public class TraceIdAspect {

    private static final Logger logger = LoggerFactory.getLogger(TraceIdAspect.class);

    // 定义切点，这里以所有带有 @Traceable 注解的方法为例
    @Pointcut("@annotation(Traceable)")
    public void traceableMethods() {}

    // 环绕通知，确保在方法执行前后设置和清除 traceId
    @Around("traceableMethods()")
    public Object aroundTraceableMethods(ProceedingJoinPoint pjp) throws Throwable {
        // 在方法执行前设置 traceId
        String traceId = TraceIdDecorator.generateTraceId(); // 假设 TraceIdGenerator 是生成 traceId 的工具类
        TraceIdDecorator.setTraceId(traceId);

        try {
            // 执行目标方法
            return pjp.proceed();
        } finally {
            // 在方法执行后清除 traceId
            TraceIdDecorator.clear();
            logger.info("TraceId cleared after method execution: {}", traceId);
        }
    }

    // 切面也可以包装子线程的执行，确保 traceId 传播
    public static <T> Callable<T> withTraceId(Callable<T> task) {
        final String parentTraceId = TraceIdDecorator.getTraceId();
        return () -> {
            try {
                TraceIdDecorator.setTraceId(parentTraceId);
                return task.call();
            } finally {
                TraceIdDecorator.clear();
            }
        };
    }
}

和一个注解标记

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Traceable {
}

然后，在业务代码中，可以这样使用： 这块因为时间原因就不继续详细写了。

public class BusinessService {  
  
    @Traceable  
    public void performTask() {  
        // 这个方法调用会被 TraceIdAspect 拦截  
        // ...  
    }  
}  

结论

跨线程的日志追踪对于现代应用程序的可维护性和可监控性至关重要。通过 LoggingUtil 和 TraceIdDecorator，提供了一种简单有效的方法来管理 traceId，让日志追踪变得更加容易。无论是在微服务架构还是在复杂的并发系统中，这些工具类都能帮助开发者保持清晰的日志线索，从而提高系统的透明度和可追踪性。

本文提供了一种优雅的方法来处理跨线程日志追踪的问题，并展示了如何在Java应用程序中实现这一目标。通过 LoggingUtil 和 TraceIdDecorator，开发者可以确保日志消息的一致性和可追踪性，从而在调试和监控时节省宝贵的时间。