SpringBoot 如果不涉及异步多线程日志跟踪相对简单,可以参考logback + MDC 搭建 springboot 的日志系统,如果涉及异步多线程就需要重写线程池,线程池有很多方法,其实没必要都重写,只要把提交线程的方法重写即可。
先讲一下 SpringBoot 请求的流转:请求到来先走的是 Filter(过滤器),然后走 Interceptor(拦截器),再走 Controller (路由器),再转到 Service(服务层),最后到持久层。日志跟踪的方式就是在 Filer 或 Interceptor 中填入 MDC 信息,这样根据 requestId 就可以串起来整个请求流程。
MDC 填充 requestId 方法 如下:
- public class RequestIdUtil {
- public static final String REQUEST_ID = "requestId";
-
- public static void setRequestId() {
- MDC.put(REQUEST_ID, UUID.randomUUID().toString());
- }
-
- public static String getRequestId() {
- return MDC.get(REQUEST_ID);
- }
-
- public static void clear() {
- MDC.clear();
- }
- }
-
Filter 中调用上述方法填充 MDC 方式如下:
- @Slf4j
- @Component
- public class RequestIdFilter implements Filter {
-
- @Override
- public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
- RequestIdUtil.setRequestId();
- log.info("entry filter........");
- try {
- filterChain.doFilter(servletRequest, servletResponse);
- } finally {
- log.info("主线程清理 mdc...");
- RequestIdUtil.clear();
- }
- }
- }
异步多线程的使用可以参考 SpringBoot开启异步多线程。当请求到来时,主线程在 Filter 中设置了 MDC 信息,但是主线程开启子线程时子线程的MDC跟主线程脱钩,解决方案核心就是开启子线程时复制一份主线程的MDC信息给子线程,所以需要重写线程池的方法(具体就是在提交线程的方法中复制MDC)。
另外,线程池的方法很多,都重写肯定是没问题的,但是有违程序猿的简约美,推荐一个方法:把所有 ThreadPoolTaskExecutor 的方法都 Override,再在每个函数第一行打上日志,然后触发异步线程池就可以看到哪些线程池函数被调用了,再重写这些被调用的方法肯定没错:
- @Slf4j
- public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
-
- /**
- * 接口请求开启的异步线程会调用下述方法
- */
- @Override
- public void execute(Runnable task) {
- log.info("接口触发的异步多线程...");
- Map
context = MDC.getCopyOfContextMap(); //复制主线程MDC - super.execute(() -> {
- if (null != context) {
- MDC.setContextMap(context); //主线程MDC赋予子线程
- } else {
- RequestIdUtil.setRequestId(); //主线程没有MDC就自己生成一个
- }
- try {
- task.run();
- } finally {
- try {
- RequestIdUtil.clear();
- } catch (Exception e) {
- log.warn("MDC clear exception:{}", e.getMessage());
- }
- }
- });
- }
-
- /**
- * 定时任务会调用下述方法
- */
- @Override
- public
Future submit(Callable task) { - log.info("定时触发的异步多线程...");
- Map
context = MDC.getCopyOfContextMap(); - return super.submit(() -> {
- if (null != context) {
- MDC.setContextMap(context); //主线程MDC赋予子线程
- } else {
- RequestIdUtil.setRequestId(); //主线程没有MDC就自己生成一个
- }
- try {
- return task.call();
- } finally {
- try {
- RequestIdUtil.clear();
- } catch (Exception e) {
- log.warn("MDC clear exception:{}", e.getMessage());
- }
- }
- });
- }
- }
线程池实现的时候就不再用 ThreadPoolTaskExecutor 而是上述 MdcThreadPoolTaskExecutor:
- @Slf4j
- @Configuration
- @EnableAsync
- public class ThreadPoolConfig {
-
- @Bean("normalThreadPool")
- public Executor executorNormal() {
- MdcThreadPoolTaskExecutor executor = new MdcThreadPoolTaskExecutor();
- executor.setCorePoolSize(1);
- executor.setMaxPoolSize(2);
- executor.setQueueCapacity(1);
- executor.setKeepAliveSeconds(60);
- executor.setThreadNamePrefix("NORMAL--");
- executor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());
- executor.initialize();
-
- return executor;
- }
-
- @Bean("scheduleThreadPool")
- public Executor executorSchedule() {
- MdcThreadPoolTaskExecutor executor = new MdcThreadPoolTaskExecutor();
- executor.setCorePoolSize(5);
- executor.setMaxPoolSize(8);
- executor.setQueueCapacity(2);
- executor.setKeepAliveSeconds(60);
- executor.setThreadNamePrefix("SCHEDULE--");
- executor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());
- executor.initialize();
-
- return executor;
- }
- }
写一个普通异步方法类:
- @Slf4j
- @Service
- public class ThreadTaskService {
- public static int threadNum = 0;
-
- @Async("normalThreadPool")
- public CompletableFuture
task(int index) { - String result = "asy start...";
- log.info("task {} start...", index);
- try {
- Thread.sleep(10000);
- result = "asy end...";
- } catch (InterruptedException e) {
- e.printStackTrace();
- }
- log.info("task {} end...", index);
- return CompletableFuture.completedFuture(result);
- }
- }
提供一个调用入口:
- @Slf4j
- @RestController
- @RequestMapping("/thread")
- public class ThreadTaskController {
- @Autowired
- ThreadTaskService taskService;
-
- @GetMapping(value = "/start")
- public String getValue() {
- threadNum++;
- CompletableFuture
result = taskService.task(threadNum); - return "hello...";
- }
- }
触发上述接口可看到日志:
子线程完美的复制集成了主线程的 requestId,并且可以看到是调用线程池的 execute(Runnable task) 方法。
准备一个定时类:
- @Slf4j
- @Configuration
- @EnableScheduling
- public class ScheduleTask {
- private static int count = 0;
- private ThreadLocal
num = new ThreadLocal<>(); -
- @Async("scheduleThreadPool")
- @Scheduled(initialDelay = 3000, fixedDelay = 1000 * 5)
- public void task() {
- count++;
- num.set(count);
- log.info("内部定时线程 {} 开启...", num.get());
- getTask();
- }
-
- private void getTask() {
- try {
- Thread.sleep(6000);
- } catch (InterruptedException e) {
- e.printStackTrace();
- }
- log.info("内部定时线程 {} 结束", num.get());
- }
- }
-
触发上述定时可看到日志:
定时任务的线程启动时因为没有主线程,所以打印的日志 requestId 为空,重新设置 requestId 后可以在后续的请求中串起来。
还有一些其他请求的跟踪,例如 feign、http 等,整体的解决方案就是在发起请求前塞一个请求id进去,然后返回时再拿出来;如有需求可自己研究。