Passing thread id between MDC and asynchronous multithreading of logs

Article directory

  • 1 MDC
    • 1.1 Introduction
    • 1.2 MDC coordinates and use
    • 1.3 Main method
  • 2 Use between multiple threads
    • 2.1 MDC Tools
    • 2.2 Interceptor definition and configuration
    • 2.3 Use in Java thread pool
      • 2.3.1 Configure thread pool
      • 2.3.2 Using ExecutorCompletionService
      • 2.3.3 Using CompletableFuture
    • 2.4 Use in Spring thread pool
      • 2.4.1 Inherit ThreadPoolTaskExecutor
      • 2.4.2 Configure thread pool

Log tracking is very important for interface troubleshooting, and can effectively and quickly locate the fault point. However, in a multi-threaded environment, if there is no support from the relevant framework, if you want to implement log tracking, you need to code to pass the log parameters of the main thread to Sub-threads, this article uses the thread pool scenario
MDC implemented
Transparent transmission of traceId parameter

1 MDC

1.1 Introduction

MDC (Mapped Diagnostic Context, Mapped Debugging Context) is a convenience provided by log4j and logback in multi-thread The function of recording logs under conditions. Some applications use multithreading to handle requests from multiple users. During a user’s use, there may be multiple different threads for processing. A typical example is a Web application server. When a user visits a certain page, the application server may create a new thread to process the request, or reuse an existing thread from the thread pool. During the duration of a user’s session, there may be multiple threads processing the user’s request. This makes it difficult to distinguish logs corresponding to different users. When it is necessary to track a user’s related log records in the system, it will become troublesome.

One solution is to use a custom log format and encode the user’s information in some way in the log records. The problem with this approach is that it requires access to user-related information in every class that uses the logger. This is only possible when logging. Such conditions are usually difficult to meet. The role of MDC is to solve this problem. MDC can be regarded as a hash table bound to the current thread, and key-value pairs can be added to it. The content contained in MDC can be accessed by code executing in the same thread. The child threads of the current thread will inherit the content of MDC in its parent thread. When you need to record logs, you only need to get the required information from MDC. The content of MDC is saved by the program at an appropriate time. For a web application, these data are usually saved at the very beginning of the request being processed

1.2 MDC coordinates and usage

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
  </dependency>
  <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-log4j12</artifactId>
      <version>1.7.21</version>
  </dependency>

log4j.xml configuration example, the custom format of the trace log is mainly set in layout of name="traceId", we use %X{traceId} to define that it will print the valuekey is traceId in MDC >, if the defined field does not have a corresponding key in MDC, it will not be printed and a placeholder will be left
Click to understand the explanation of the Loback.xml file

1.3 Main method

API Description:

  • clear(): Remove all MDCs
  • get (String key): Get the value of the specified key in the current thread MDC
  • getCopyOfContextMap(): Get the MDC from the memory and pass it to the thread
  • put(String key, Object o): Store the specified key-value pair in the MDC of the current thread
  • remove(String key): delete the specified key-value pair in the current thread MDC
  • setContextMap(): Pass the MDC content of the parent thread to the child thread

MDC transfer between asynchronous threads:
When using the put of MDC, the child thread will set the inheritableThreadLocals variable in the parent thread to the inheritableThreadLocals of the child thread when it is created, and MDC is internally implemented with InheritableThreadLocal, so it will bring the context in the parent thread to the child thread
But in the thread pool, since the thread will be reused, the thread itself will only be initialized once, so when the thread is reused later, the initialization operation will not be performed, and there will be no parent thread inheritableThreadLocals The process of copying to the child thread, if you want to pass the context of the parent thread at this time, you must use the getCopyOfContextMap method

2 Use between multiple threads

2.1 MDC Tools

Define the MDC tool class, support Runnable and Callable, the purpose is to set the traceId of the parent thread to the child thread

import org.slf4j.MDC;
import org.springframework.util.CollectionUtils;

import java.util.Map;
import java.util.concurrent.Callable;

/**
 * @Description encapsulates MDC for passing to thread pool
 */
public class MDCUtil {<!-- -->
    public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {<!-- -->
        return () -> {<!-- -->
            if (CollectionUtils.isEmpty(context)) {<!-- -->
                MDC. clear();
            } else {<!-- -->
                MDC.setContextMap(context);
            }
            try {<!-- -->
                return callable. call();
            } finally {<!-- -->//Clear sub-threads to avoid memory overflow, just for the same reason as ThreadLocal.remove()
                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 void setMDCContextMap(final Map<String, String> context) {<!-- -->
        if (CollectionUtils.isEmpty(context)) {<!-- -->
            MDC. clear();
        } else {<!-- -->
            MDC.setContextMap(context);
        }
    }

}

2.2 Interceptor definition and configuration

package demo;

import org.slf4j.MDC;
import org.springframework.lang.Nullable;
import org.springframework.util.StringUtils;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.Arrays;
import java.util.List;

public class RequestInterceptor extends HandlerInterceptorAdapter {<!-- -->

    private static final List<String> paramSet = Arrays.asList("traceId");

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {<!-- -->
        this.setParam(request);
        return super. preHandle(request, response, handler);
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable Exception ex) throws Exception {<!-- -->
        MDC. clear();
    }

    private void setParam(HttpServletRequest request) {<!-- -->
        // Set the parameters to be placed in the MDC
        for (String key : paramSet) {<!-- -->
            String val = request. getHeader(key);
            if (!StringUtils.isEmpty(val)) {<!-- -->
                MDC. put(key, val);
            }
        }
    }

}

Interceptor configuration

import demo.RequestInterceptor;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

/**
 * Intercept WEB requests
 */
@Configuration
public class InterceptorConfig implements WebMvcConfigurer {<!-- -->

    @Override
    public void addInterceptors(InterceptorRegistry registry) {<!-- -->
        registry.addInterceptor(new RequestInterceptor());
    }

}

2.3 Use in Java thread pool

2.3.1 Configure thread pool

@Configuration
public class ThreadPoolService {<!-- -->
@Bean
public ThreadPoolExecutor threadPoolExecutor() {<!-- -->
ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor
(4, 8, 10,
                TimeUnit. SECONDS, new LinkedBlockingQueue<Runnable>(5536),
                new ScheduledThreadFactory("demo-"), new ThreadPoolExecutor. CallerRunsPolicy());
return threadPoolExecutor;
}
}

Click to learn about the thread pool

2.3.2 Using ExecutorCompletionService

Use ExecutorCompletionService to implement multi-threaded calls
Click to learn more about ExecutorCompletionService

/**
 * Use MDC to pass traceId
 */
public class Demo {<!-- -->

@Autowired
private ThreadPoolExecutor threadPoolExecutor;

public void demo() {<!-- -->
ExecutorCompletionService ecs = new ExecutorCompletionService(threadPoolExecutor);
ecs.submit(MDCUtil.wrap(new TestMDC(), MDC.getCopyOfContextMap()));
}
\t
class TestMDC implements Callable {<!-- -->
@Override
public Object call() throws Exception {<!-- -->
// TODO code logic
return null;
}
}
}

2.3.3 Using CompletableFuture

Use CompletableFuture to implement multi-threaded calls, where CompletableFuture running results are collected,
Click to learn more about CompletableFuture

public class Result {<!-- -->}
/**
 * Use MDC to pass traceId
 */
public class Demo {<!-- -->

@Autowired
private ThreadPoolExecutor threadPoolExecutor;

    private CompletableFuture<Result> test() {<!-- -->
    
        Map<String, String> copyOfContextMap = MDC. getCopyOfContextMap();
        
        return CompletableFuture. supplyAsync(() -> {<!-- -->
        
            // must be set before printing the log
            MDCUtil.setMDCContextMap(copyOfContextMap);
            //MDC.put("subTraceId",''); //If you need to add the thread tracking number to the sub-thread, you can set it here
            // TODO business logic
            return new Result();
            
        }, threadPoolExecutor).exceptionally(new Function<Throwable, Result>() {<!-- -->
            /**Catch exceptions, will not cause the entire process to be interrupted**/
            @Override
            public Result apply(Throwable throwable) {<!-- -->
                log.error("Thread [{}] has an exception [{}], continue to execute other threads", Thread.currentThread().getName(), throwable.getMessage());
                return null;
            }
        });
    }
}

2.4 Spring thread pool use

2.4.1 Inherit ThreadPoolTaskExecutor

public class ThreadPoolMdcWrapper extends ThreadPoolTaskExecutor {<!-- -->

    public ThreadPoolMdcWrapper() {<!-- -->

    }

    @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()));
    }
}

2.4.2 Configure thread pool

Inherit ThreadPoolTaskExecutor to rewrite the thread execution method. At this point, we have finished most of the preparatory work, and the most important thing left is to let the program use our encapsulated thread pool. We can directly use our encapsulated thread pool when declaring the thread pool (because it inherits ThreadPoolTaskExecutor)
Click to learn about Spring thread pool configuration

@Bean
public ThreadPoolTaskExecutor taskExecutor() {<!-- -->
    ThreadPoolTaskExecutor taskExecutor = new ThreadPoolMdcWrapper();
    //Number of core threads, the default is 1
    taskExecutor.setCorePoolSize(1);
    //The maximum number of threads, the default is Integer.MAX_VALUE
    taskExecutor.setMaxPoolSize(200);
    //The maximum length of the queue, generally need to set the value >=notifyScheduledMainExecutor.maxNum; the default is Integer.MAX_VALUE
    taskExecutor.setQueueCapacity(2000);
    //The thread pool maintains the idle time allowed by the thread, the default is 60s
    taskExecutor.setKeepAliveSeconds(60);
    //Thread pool's processing strategy for rejected tasks (no threads available)
    taskExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());
    // Initialize the thread pool
    taskExecutor. initialize();
    return taskExecutor;
}

At this point, the preparatory work we have done, the transformation work is over, and the rest is to use it. As long as the program is called asynchronously, the declared taskExecutor thread pool is used to call, and the Traceid can be passed correctly in the thread context.