Spring Boot 2系列(四十七)：Spring AOP 实现API接口处理请求耗时监控

本篇文章算是 Spring Boot 2实践系列(四十六)：API接口请求限制之AOP与拦截器实现 的下篇，也是基于拦截器和 AOP 两种方式实现对 API 接口请求响应的耗时进行统计，也是对涉及的知识点学习和巩固。

开发任何一个系统，都应当对 API 接口响应时长进行监控以了解系统性能，帮助判断性能瓶颈（当然很多小公司或小系统并没有这个意识，或有这个意识但没有落地实行）。

收集响应时长数据，可以与监控系统联动，或对接短信系统、IM 即时通信系统 或 邮件系统实现告警通知。

大型系统可能会有多层监控（数据库层，应用层，网络层等），来缩小判断耗时的具体范围(节点)，查找性能短板，在分布式微服务环境下可以在网关层实现统一监控，单个微服务应用也需要对自己的 API 响应时长进行监控。例如，Spring Cloud 的分布式链路跟踪组件 Sleuth 就有收集请求链路上各个节点的消耗时长。

Spring Boot 项目集成 spring-boot-starter-actuator 也能收集接口的请求次数，响应时长，接口状态等指标。

拦截器方式

先了解下拦截器的特性和方法，可参考 SpringMVC之HandlerInterceptor拦截器。注：过滤器也能实现同样的功能。

拦截器

拦截器接口 HandlerInterceptor 提供了三个方法来实现对请求前、请求后，响应后进行自定义处理，并且拦截器的前置处理和后置处理是具体关联性的。

• **preHandle()**：在 Controller 方法执行之前执行。即在 HandlerMapping 确定适当的处理程序对象之后调用，但在HandlerAdapter 调用处理程序之前调用。关于 Spring MVC 的执行流程，可参考 SpringMVC执行流程。
• **postHandle()**：在 Controller 方法执行之后执行。即在 HandlerAdapter 实际调用处理程序之后，但在DispatcherServlet 呈现视图之前调用。
• **afterCompletion()**：完成请求处理后（即渲染视图之后）的回调。 将在处理程序执行的任何结果上被调用，从而允许适当的资源清理。

思路

要统计接口处理请求的时长，可以在拦截器的 preHandle() 方法记录请求开始时间（startTime），在 afterCompletion() 方法中记录请求处理完后的结束时间（endTime），请求处理时间(响应时间) = 结束时间 - 开始时间。

这里有个问题是 afterCompletion() 方法要拿到 preHandle() 方法记录的开始时间才能计算，这个记录时间不能定义成类变量，而是与当前请求的线程绑定的，可以使用 ThreadLocal 将开始时间绑定到当前线程，在 afterCompletion() 方法里从 ThreadLocal 取出开始时间（startTime）。

实现

API 耗时统计

理解上面描述的拦截器方法和原理后，实现起来就简单了（重点在于理解原理，综合撑握的知识点灵活应用，理清思路，编码就 so easy）。

1. 定义拦截器

   @Component
   @Order(Integer.MAX_VALUE - 1000)
   public class APIHandleTimeInterceptor implements HandlerInterceptor {
       private static final Logger logger = LogManager.getLogger(APIHandleTimeInterceptor.class);
   
       private NamedThreadLocal<Long> threadLocal = new NamedThreadLocal("StopWatch_StartTime");
   
       @Override
       public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
               throws Exception {
           logger.info("请求进入API处理时长拦截器.................");
           //1.开始时间
           long startTime = System.currentTimeMillis();
           //2.绑定变量(只有当前请求线程可见)
           threadLocal.set(startTime);
           return true;
       }
   
       @Override
       public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
                                   @Nullable Exception ex) throws Exception {
           //3.结束时间(请求处理完成)
           long endTime = System.currentTimeMillis();
           //4.取出开始时间
           long startTime = threadLocal.get();
           //5.计算耗时
           long consumeTime = endTime - startTime;
           //此处认为处理时间超过500毫秒的请求为慢请求
           //此处可以做一些复杂的告警通知,如与 IM即时通信应用、邮件系统、短信系统对接
           if (consumeTime > 500) {
   //            logger.info(String.format("【WARN】%s consume %d millis", request.getRequestURI(), consumeTime));
               logger.info("【WARN】API:{}, consumeTime:{} millis", request.getRequestURI(), consumeTime);
           } else {
   //            logger.info(String.format("【NORMAL】%s consume %d millis", request.getRequestURI(), consumeTime));
               logger.info("【NORMAL】API:{}, consumeTime:{} millis", request.getRequestURI(), consumeTime);
           }
           logger.info("请示处理完成从API处理时长拦截器结束.................");
   
       }
   
       @Override
       public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
                              @Nullable ModelAndView modelAndView) throws Exception {
       }
   }

2. 配置拦截器使其生效

   @Configuration
   public class WebConfig implements WebMvcConfigurer {
   
       @Override
       public void addInterceptors(InterceptorRegistry registry) {
           registry.addInterceptor(new LoginInterceptor())
                   .addPathPatterns("/**")
                   .excludePathPatterns("/login");
           registry.addInterceptor(new APIHandleTimeInterceptor())
                   .addPathPatterns("/**");
   //        registry.addInterceptor(new RequestLimitInterceptor());
       }
   }

API 请求频率

拦截器这里可以对 API 接口访问频率进行统计。在 preHandle() 方法中通过 Request 拿到 URI 进行存储计算。

例如，要计算每个接口每天调用的频率，可以将数据写入到 Redis，使用 Sorted Set 数据类型，每天的时间作为 Key，URI 做为元素，访问次数做为 权重分，接口再次被访问时则增加该元素的权重分，使用时可直接使用命令获取已排好序的元素集合。

备注：

拦截器实现方式有个弊端，即如果采用的是路径传参， request.getRequestURI() 方法会取得包含路径参数的 URI，这样每个不同的参数都会被误认为是不同的 URI，无法识别出真正的 URI。

或许可以通过请求映射处理器(RequestMappingHandlerMapping) 获取所有 URI ，再使用正则匹配请求进来的 URI 来找到正确的 URI，待验证。。。。可参考 SpringMvc请求如何获取相关HandlerMapping。

AOP切面方式

AOP 的相关知识可以参考 Spring 之 AOP理解 和 使用。

思路

AOP 的通知类型中有一种是 **环绕通知(around)**，即可以在方法执行的前和执行后对代理的目标方法进行增强，这个特性就可以满足对方法处理请求的时长进行计算。

使用环绕通知，在方法执行前获取当前时间做为开始时间(startTime)，在方法执行后获取当前时间做为结束时间(endTime)，方法处理请求的时长 = 结束时间 - 开始时间。

实现

@Aspect
@Component
public class RequestHandleTimeAspect {
    private static final Logger logger = LogManager.getLogger(RequestHandleTimeAspect.class);

    @Autowired
    private HttpServletRequest request;

    @Pointcut("execution(* com.springboot.demo.controller.*.*(..))")
    public void pointcut() {
    }

    @Around("pointcut()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        //开始时间
        long startTime = System.currentTimeMillis();

        //执行代理目标方法
        Object obj = joinPoint.proceed();
        Thread.sleep(200);

        //结束时间
        long endTime = System.currentTimeMillis();

        //处理时间
        long costTime = endTime - startTime;

        Object target = joinPoint.getTarget();
        //代理目标对象类名
        String className = target.getClass().getSimpleName();
        //代理目标对象全限定类名
        String fullClassName = target.getClass().getName();
        //切点的方法名
        String methodName = joinPoint.getSignature().getName();
        //请求URI
        String requestURI = request.getRequestURI();

        //获取HttpServletResponse来自定义响应数据
        HttpServletResponse response = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getResponse();

        if (costTime > 180) {
            logger.info("【WARN】URI:{}, API:{}, costTime:{} millis", requestURI, className + "." + methodName, costTime);
        } else {
            logger.info("【NORMAL】处理方法:{}, 处理请求耗时:{}", fullClassName + "." + methodName, (endTime - startTime));
        }
        return obj;
    }
}

注意：网上有些例子是在切面类里定义类变量（startTime），然后在 @Before 注解方法中给 startTime 赋值；在 @After注解方法中取当前时间为 endTime ，请求处理时间 = endTime - startTime。这种处理是不可取的，很明显会存在线程安全问题。

若要使用这种处理且解决线程安问题，可以定义一个 ThreadLocal 对象，在 @Before 注解的方法中将 startTime 值设置到 ThreadLocal 对象中绑定为当前线程可见，在 @After 注解的方法中从 ThreadLocal 取出 startTime 计算请求处理时间。可参考上面 拦截器方式 中的实现处理。

备注

在 AOP 中要获取 HttpServletRequest，可以使用注入方式，但不能注入 HttpServletResponse，可以通过下面方式获取：

HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();

HttpServletResponse response = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getResponse();

接口优化

接口优化是个系统工程，涉及到数据库、缓存、网络、CDN、业务逻辑等等，一时难以概述。下面引用几篇文章：

1. 优化API接口响应速度
2. api接口性能优化问题
3. 接口优化总结

其它参考

1. Spring项目中监控方法执行时间：提供了另一 种基于 AOP 实现思路，有参考价值。
2. 使用SpringAOP获取一次请求流经方法的调用次数和调用耗时