Spring Boot AOP 拦截请求统计耗时

文摘职场 2024-05-11 11:01 江苏

复习
上学时都背过，Spring框架的2大明星功能：IOC与DI。从SSH到SSM到SpringMVC再到今天的SpringBoot，从复杂的XML配置到注解再到一些提供默认功能的注解，无论如何演变，2大明星地位依然岿然不动。
IoC：
控制反转（IoC，Inversion of Control），是一个概念、一种思想。控制反转就是对对象控制权的转移，从程序代码本身反转到了外部容器。把对象的创建、初始化、销毁等工作交给spring容器来做。由spring容器控制对象的生命周期。
DI：
依赖注入：Dependency Injection。依赖注入DI是指程序运行过程中，若需要调用另一个对象协助时，无须在代码中创建被调用者，而是依赖于外部容器，由外部容器创建后传递给程序。依赖注入是目前最优秀的解耦方式。依赖注入让Spring的Bean之间以配置文件的方式组织在一起，而不是以硬编码的方式耦合在一起的。
二者关系：
它们是同一个概念的不同角度描述，IoC是一个概念、一种思想，其实现方式多种多样，当前比较流行的实现方式之一是DI。由于控制反转概念比较含糊（可能只是理解为容器控制对象这一个层面，很难让人想到谁来维护对象关系），所以2004年大师级人物Martin Fowler又给出了一个新的名字：“依赖注入”，相对IoC 而言，依赖注入明确描述了被注入对象依赖IOC容器配置依赖对象。
AOP：
AOP（Aspect Oriented Programming——面向切面编程）一种面向对象编程（OOP）的技术，在不修改源码的基础上，它允许在程序运行时动态地添加横向关注点到应用程序中实现功能增强。如登录校验、权限认证、日志记录和事务处理等。
AOP术语：
切面（Aspect）：AOP的核心，定义了一系列与横向关注点相关的通知（Advice）。
切点（Pointcut）：具体拦截的某个业务点。
通知（Advice）：是要在横向关注点发生的特定点执行的代码。
通知类型：
@Before(前置通知)：在目标业务方法执行之前执行。
@After(后置通知)：在目标业务方法执行之后执行。
@AfterReturning(返回通知)：在目标业务方法返回结果之后执行。
@AfterThrowing(异常通知)：在目标业务方法抛出异常之后。
@Around(环绕通知)：功能强大，可代替以上四种通知，还可以控制目标业务方法是否执行以及在何时执行。
背景:
前端同学老是说某些接口访问要很久，最近又正好要把阿里云从上海迁到乌兰察布。那这个慢到底是业务慢还是前端到后端这期间的延时呢？需要想个办法定位一下，可以借助Fiddler工具，也可以分别在后端收到请求时和响应前打一个时间看看时间差，当然客官还可以去模仿《SpringBoot集成zipkin和kafak》这篇的步骤，一看便知。本篇就用AOP实现一个后端逻辑处理耗时计算功能。
流程梳理
a.定义切面（写一个类），使用@Aspect注解。
b.在切面中定义通知（写一个方法）。使用@Before、@After或@Around等注解表明啥时候运行通知逻辑。
c.定义切入点，表明当满足什么条件时执行通知。

上述流程中，c相对比较麻烦，主要是因为切入点的表达式不太会搞。逻辑倒是没清楚的，拦截所有请求，那自然会想到所有***controller类，而这个类在我们的项目结构中，多数都放在包名包含controller的包下，所以自然想到切入点表达式拦截包含controller关键字的包名，该如何写这个表达式呢？
```
execution(modifiers-pattern? ret-type-pattern declaring-type-pattern? name-pattern(param-pattern) throws-pattern?)
```
modifiers-pattern?：方法的修饰符（public/private/protected），支持通配符(*)，该部分省略时匹配任意修饰符。
ret-type-pattern：指定方法的返回值类型，支持通配符，可以使用*来匹配所有的返回值类型。
declaring-type-pattern?：指定方法所属的类（class），支持通配符，该部分可以省略。
name-pattern：指定要匹配的方法名，支持通配符，可以使用*来匹配任意方法(query* 匹配以query开关的方法)。
param-pattern：指定方法声明中的形参列表和数量，支持两个通配符，即"*"和".."。举例：
()——匹配没有参数的方法。
(..)——匹配任意数量参数的方法。
(*)——匹配一个任意类型参数的方法。
(*,Byte)——匹配有两个参数的方法，并且第一个为任意类型，第二个为Byte类型。
throws-pattern：匹配抛出异常类型，支持通配符，省略时匹配任意类型
来几个例子：
```
// 匹配public方法execution(public * *(..))
// 匹配名称以query开头的方法execution(* query*(..))
// 匹配controller包及其子包的类或接口 有点像我要的execution(* com.xxx.controller..*(..))
```

动手

查资料找到了我大概需要的表达式，那就先来个简单版：

/** * @Title: * @Package * @Description: 后端业务耗时切面 * @author: siri * @date: * @version: V1.0 */@Aspect@Componentpublic class HttpTimeAspect {       @Autowired    private MicroMeterTool microMeterTool;
    //切入点 包含controller的包名    @Pointcut("execution(* com.xxx..controller.*.*(..))")    public void controllerPoint() {    }
    //通知：因为我需要在原逻辑前后计算时间，所以用的环绕通知    @Around("controllerPoint()")    public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();        HttpServletRequest request = attributes.getRequest();        String URI = request.getRequestURI();
        long s = System.currentTimeMillis();        //try块保证不影响原逻辑        try{           return joinPoint.proceed();        }finally {            //把耗时结果放到prometheus            long e = System.currentTimeMillis();            // microMeterTool.timeGauge("http_req_url", URI, (e - s));        }    }}

写完了，不太放心，在群里问了下大家，有没有controller类的包名不包含controller的。不问不知道，还真又同学回复，新的项目结构中包含controller的包名是web，相当于上面这个表达式拦截不到了，可咋整呢？灵机一动，变通一下，我拦截所有的请求注解：

@Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping) || " +          "@annotation(org.springframework.web.bind.annotation.PostMapping) ||" +          "@annotation(org.springframework.web.bind.annotation.GetMapping) ||" +          "@annotation(org.springframework.web.bind.annotation.PutMapping) ||" +          "@annotation(org.springframework.web.bind.annotation.PatchMapping) ||" +          "@annotation(org.springframework.web.bind.annotation.DeleteMapping)")public void controllerPoint() {}

咋一看没问题的，但实际测试过程发现：如果项目有的是feign通信，那么也会被拦截到，例如：

@RequestMapping(value = "${feign.taskcollect.route}")public interface SNSClient {    @PostMapping("/file/showContent")    BaseResponseEntity<Map<String,Object>> downloadAndAnalysisFile(@RequestBody ShowFileContentReq req);}

既然注解是可以行的通的，那有没有一种办法，可以只过滤包含controller的类，突然看到，多个之之间可以用逻辑表达式，突然间脑袋又开光了，把前面2个条件加在一起不就可以解决么？于是下面的版本就出来了：

@Pointcut("execution(* com.xxx..*Controller.*(..)) && " +        "(@annotation(org.springframework.web.bind.annotation.RequestMapping) || " +        "@annotation(org.springframework.web.bind.annotation.PostMapping) ||" +        "@annotation(org.springframework.web.bind.annotation.GetMapping) ||" +        "@annotation(org.springframework.web.bind.annotation.PutMapping) ||" +        "@annotation(org.springframework.web.bind.annotation.PatchMapping) ||" +        "@annotation(org.springframework.web.bind.annotation.DeleteMapping))")public void controllerPoint() {}

上面的表达式可以再加上包名包含web的写法，至此比较完整的雏形就已经定好了。代码还应该更灵活，比如有的服务不想统计耗时、有的URI想过滤掉怎么弄？

优化

上明的问题，我们可以通过配置文件进行灵活管理（在对应的类上加@RefreshScope可以保证你配置的热加载）。

@Value("${xpilot.tools.http_time.filter_uri:}")private Collection<String> FILTER_URI;
@Value("${xpilot.tools.http_time.record:true}")private Boolean RECORD_TIME;

@Around("controllerPoint()")public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {    if(!RECORD_TIME){        return joinPoint.proceed();    }    long s = System.currentTimeMillis();    String URI = null;    try {        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();        HttpServletRequest request = attributes.getRequest();        URI = request.getRequestURI();    }catch (Throwable t){        log.error("HttpTimeAspect analysis req:",t);    }    try{        return joinPoint.proceed();    }finally {        try {            long e = System.currentTimeMillis();            if(!StringUtils.isBlank(URI) && !CollectionUtils.isEmpty(FILTER_URI) && !FILTER_URI.contains(URI)){                microMeterTool.appAccessTimeGauge( URI, (e - s));            }        }catch (Throwable t){            log.error("HttpTimeAspect record time:",t);        }    }}

为了最大限度不影响原有逻辑，将URI的解析和时间统计都用try块包裹。再一次自测过程中发现存在有的时候HttpServletRequest是空，触发了URI解析异常，于是再次优化URI的获取方式：

private String getUriFromJoinPoint(ProceedingJoinPoint joinPoint){        String uri = null,sub = null;        try {            Signature signature = joinPoint.getSignature();            if (!(signature instanceof MethodSignature)) {                return null;            }            MethodSignature methodSignature = (MethodSignature) signature;            Method method = methodSignature.getMethod();
            Class<?> declareClass = method.getDeclaringClass();            RequestMapping controllerAnnotation = declareClass.getAnnotation(RequestMapping.class);
            Annotation[] methodAnnotations = method.getDeclaredAnnotations();            for (Annotation methodAnnotation: methodAnnotations) {                if (methodAnnotation instanceof RequestMapping) {                    RequestMapping requestMapping = (RequestMapping) methodAnnotation;                    sub = requestMapping.value()[0];                } else if (methodAnnotation instanceof PostMapping) {                    PostMapping postMapping = (PostMapping) methodAnnotation;                    sub = postMapping.value()[0];                } else if (methodAnnotation instanceof GetMapping) {                    GetMapping getMapping = (GetMapping) methodAnnotation;                    String[] value = getMapping.value();                    //fix match @GetMapping(path = ...)                    sub = null == value || value.length<=0 ? getMapping.path()[0] : value[0];                } else if (methodAnnotation instanceof PutMapping) {                    PutMapping putMapping = (PutMapping) methodAnnotation;                    sub = putMapping.value()[0];                } else if (methodAnnotation instanceof PatchMapping) {                    PatchMapping patchMapping = (PatchMapping) methodAnnotation;                    sub = patchMapping.value()[0];                } else if (methodAnnotation instanceof DeleteMapping) {                    DeleteMapping deleteMapping = (DeleteMapping) methodAnnotation;                    sub = deleteMapping.value()[0];                }            }            //avoid class no request mapping            uri = null == controllerAnnotation || controllerAnnotation.value().length<=0  ? sub : controllerAnnotation.value()[0]+sub;        }catch (Throwable t){            log.error("XpilotHttpTimeAspect analysis req:",t);        }        uri = StringUtils.isBlank(uri) ? null : uri.replaceAll("//","/");        return uri;    }

耗时

上面我们通过切面拿到了URI，计算出耗时后就写如Prometheus，但每次都这样也浪费时间，所以需要稍作调整，用一个容器暂存耗时结果，如果15秒内同一个URL再次请求过来，则比较本次耗时和容器中记录的时间，留下大的一个，然后定时把这样的一个记录结果写入Prometheus，统计时间该国15秒内最大的URI耗时，部分如下：

//耗时容器private final ConcurrentHashMap<String, Long> recordURIMaxTimeMap = new ConcurrentHashMap<>(1<<6);

 @Around("controllerPoint()")public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {    if(!xpilotHttpProperties.getRecordTime()){        return joinPoint.proceed();    }    long s = System.currentTimeMillis();    String URI = getUriFromJoinPoint(joinPoint);    try{        return joinPoint.proceed();    }finally {        try {            long e = System.currentTimeMillis();            if(!StringUtils.isBlank(URI) && (CollectionUtils.isEmpty(xpilotHttpProperties.getFilterUri()) || !xpilotHttpProperties.getFilterUri().contains(URI))){                long diff = e-s;                //耗时比较 保留大的                Long cache = recordURIMaxTimeMap.getOrDefault(URI, 0L);                if(diff > cache){                    recordURIMaxTimeMap.put(URI,diff);                }            }        }catch (Throwable t){            log.error("HttpTimeAspect record time:",t);        }    }}
//定时推送@Scheduled(fixedDelay = 15000,initialDelay = 0)public void recordTime(){    if(CollectionUtils.isEmpty(recordURIMaxTimeMap)){        log.debug("the cache collection is empty.waiting next time :)");        return;    }    for (Map.Entry<String, Long> entry : recordURIMaxTimeMap.entrySet()) {        //release and get time        microMeterTool.appAccessTimeGauge(entry.getKey(), entry.getValue());        recordURIMaxTimeMap.put(entry.getKey(),0L);    }}

效果展示
运行以上逻辑产生的数据，需要告诉运维同学配合从promethues解析相关指标，通过grafana呈现，参考如下：
开发同学只需要打开监控大盘，选择负责的服务，就可以看到对应的数据，依据该值，可以定位应用的健康与否，也可用于判断逻辑处理时长。

P.S：关于Promethes如何搭建、如何监控服务、如何自定义监控指标请查看《SpringBoot集成Prometheus》一文最后的自定义指标部分，祝你好运气。

划水专用：
https://zhuanlan.zhihu.com/p/513920894
https://www.cnblogs.com/dshore123/p/11823849.html

风里雨里，我一直等你

五花马，千金裘，呼儿将出换美酒，与尔同销万古愁。
李白——《将进酒》

晚霞程序员

一位需要不断学习的30+程序员……