利用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某次请求的唯一线程名，就可以看到程序处理本次请求的所有日志了。

如果没有这个切面来reset线程名，因为线程池的线程是可复用的，多次请求的工作线程可能是一个。那么，按线程名去grep日志的话，得到的可就不止于某一次请求的了，这对于高频访问的系统的排障，会带来诸多不便，甚至会导致误判。