利用AOP来变更工作线程的名字,来快速过滤出一次请求的所有日志


本文呢,还是java项目,这次用AOP来实现。

至于为什么要改threadName,为什么要用AOP,就不再铺垫赘述了。Talk is cheap, show me thecode。下面代码可以直接使用,拿走不谢。

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日志的话,得到的可就不止于某一次请求的了,这对于高频访问的系统的排障,会带来诸多不便,甚至会导致误判。


原文链接:https://www.cnblogs.com/buguge/p/13531945.html