利用AOP來變更工作線程的名字，來快速過濾出一次請求的所有日志

如何快速過濾出一次請求的所有日志？

關于日志鍊路追蹤，之前在.net項目和java項目裡有過不同的最佳實踐。見下面連結。

▄︻┻┳═一巧用CurrentThread.Name來唯一标記一次請求的所有日志

▄︻┻┳═一巧用CurrentThread.Name來唯一标記一次請求的所有日志（續）

▄︻┻┳═一巧用CurrentThread.Name來唯一标記一次請求的所有日志（完結篇）

▄︻┻┳═一asp.net攔截器

▄︻┻┳═一巧用CurrentThread.Name來唯一标記一次請求的所有日志（java-logback篇）

本文呢，還是java項目，這次用AOP來實作。

至于為什麼要改threadName，為什麼要用AOP，就不再鋪墊贅述了。Talk is cheap, show me the code。下面代碼可以直接使用，拿走不謝。

package com.aop;

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;

import java.util.Random;

/**
 * 【日志鍊路追蹤】重置工作線程名為唯一字元串，
 * 這樣在生産排障時，可以快速過濾一次請求的所有日志
 */
@Slf4j
@Component
@Aspect
public class WorkThreadNameAspect {
    @Pointcut("execution(public * com.clz.*.*(..))")
    public void pointCut() {
    }

    ThreadLocal<String> threadLocal = new ThreadLocal<>();

    //    @Before("pointCut()")
//    public void before(JoinPoint joinPoint) {
    public void setThreadName(JoinPoint joinPoint) {
//        if (Thread.currentThread().getName().contains("-")) {
        String threadNameFlag = getMethodSignature(joinPoint);
        String before = Thread.currentThread().getName();
        String s = threadLocal.get();
        if (threadLocal.get() == null) {
            String threadName = threadNameFlag + System.currentTimeMillis() + "_" + new Random().nextInt(1000);
            threadLocal.set(threadName);
            Thread.currentThread().setName(threadName);
        }
        log.debug("threadName={}→→→{}, threadLocal.get()={}→→→{}", before, Thread.currentThread().getName(), s, threadLocal.get());
//        }
    }

    String getMethodSignature(JoinPoint joinPoint) {
        return joinPoint.getSignature().getDeclaringType().getSimpleName() + "_" + joinPoint.getSignature().getName();
    }

    @After("pointCut()")
    public void after(JoinPoint joinPoint) {
        String threadNameFlag = getMethodSignature(joinPoint);
        if (threadLocal.get() != null && threadLocal.get().contains(threadNameFlag)) {
            log.debug("remove name {}", Thread.currentThread().getName());
            threadLocal.remove();
        }
    }

    @Around("pointCut()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        setThreadName(joinPoint);
        long start = System.currentTimeMillis();
        try {
            return joinPoint.proceed(joinPoint.getArgs());
        } finally {
            log.info("{} duration=執行耗時={}ms", getMethodSignature(joinPoint),
                    System.currentTimeMillis() - start);
        }
    }
}      

注意，aspectj裡各個advice的執行順序，Around advice是先于Before advice的，是以設定線程名要在@Around注解的方法裡來執行。下圖是advice的執行順序。

好了。如下多線程模拟并發來測試，從運作結果可以看出，想定位某一次請求的日志，就友善多了。

package com.clz;

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.junit.runner.RunWith;import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringRunner;

import java.util.concurrent.LinkedBlockingDeque;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;

@Slf4j
@SpringBootTest
@RunWith(SpringRunner.class)
class AOPTest {
    @Autowired
    private Class1 class1;

    @Test
    public void testWorkThreadName() throws InterruptedException {
        class1.test();

        Thread.currentThread().setName("mmmmmmmm");
        log.info("異步多線程測試");
        
        ThreadPoolExecutor poolExecutor = new ThreadPoolExecutor(5, 5, 10, TimeUnit.MILLISECONDS, new LinkedBlockingDeque<>(5));
        Thread.sleep(5);
        for (int i = 0; i < 2; i++) {
            poolExecutor.execute(() -> {
                class1.test();
//                csdfsdafdsfdsfdsf.test();
            });
        }
        poolExecutor.shutdown();
        poolExecutor.awaitTermination(2, TimeUnit.SECONDS);
    }
}      

 如下是執行結果。

那麼，有了這個重置線程名的切面以後，當我們在linux伺服器上定位log時，實作了slf4j-api的日志架構，不管是log4j/log4j2，還是logback，隻要每條日志的字首攜帶線程名（預設是有的，見pattern辨別符%t或%thread），直接grep某次請求的唯一線程名，就可以看到程式處理本次請求的所有日志了。