背景

在一些重要接口，可能需要打印出方法的耗时，可能有其他的开源框架的方式来统计，目前的能力也只能想到这种方式了

实现

spring boot 版本 2.4.4

添加依赖

  1. // spring-boot aop
  2. implementation 'org.springframework.boot:spring-boot-starter-aop'
  3. // hutool 工具使用了里面的一些工具类
  4. implementation 'cn.hutool:hutool-all:5.5.4'
  5. // 项目使用了 lombok 的 @Slf4j 注解
  6. compileOnly 'org.projectlombok:lombok:1.18.18'
  7. annotationProcessor 'org.projectlombok:lombok:1.18.18'

编写一个注解，用于标识哪些方法需要打印耗时信息

  1. package cn.mrcode.timewatch;
  3. import java.lang.annotation.*;
  5. /**
  6.  * 仅作用在方法上
  7.  *
  8.  * @author zq
  9.  */
  10. @Target(ElementType.METHOD)
  11. @Retention(RetentionPolicy.RUNTIME)
  12. @Documented
  13. public @interface TimeWatch {
  14.     /**
  15.      * 该方法名称，业务名称
  16.      *
  17.      * @return
  18.      */
  19.     String value() default "";
  20. }

编写切面

  1. package cn.mrcode.timewatch;
  3. import lombok.extern.slf4j.Slf4j;
  4. import org.aspectj.lang.ProceedingJoinPoint;
  5. import org.aspectj.lang.annotation.Around;
  6. import org.aspectj.lang.annotation.Aspect;
  7. import org.springframework.stereotype.Component;
  9. import java.time.Instant;
  10. import java.time.temporal.ChronoUnit;
  12. /**
  13.  * 方法执行时间日志打印
  14.  */
  15. @Component
  16. @Aspect
  17. @Slf4j
  18. public class TimeWatchAspect {
  19.     // 直接扫描包含 TimeWatch 注解的方法，所以在方法内部就不用再判定注解了
  20.     // 第一个 @annotation 选择 pointcut, 第二个 @annotation 限定参数类型，表示将目标方法上的注解定义对象注入进来，就不再需要我们自己从 point 上去获取了
  21.     // 这里也可以直接使用 @annotation(timeWatch) 里面的值则是 方法名称
  22.     @Around("@annotation(TimeWatch) && @annotation(timeWatch)")
  23.     public Object handler(ProceedingJoinPoint point, TimeWatch timeWatch) throws Throwable {
  24.         // 不注入的话，就需要使用这种反射方式自己获取
  25.         // final TimeWatch timeWatch = ((MethodSignature) point.getSignature()).getMethod().getAnnotation(TimeWatch.class);
  26.         Instant now = Instant.now();
  27.         try {
  28.             Object proceed = point.proceed();
  29.             return proceed;
  30.         } finally {
  31.             Instant end = Instant.now();
  32.             log.info("[{}] 耗时:{} 毫秒 | {} 秒 | {} 分钟 | {} 小时", timeWatch.value(),
  33.                     now.until(end, ChronoUnit.MILLIS),
  34.                     now.until(end, ChronoUnit.SECONDS),
  35.                     now.until(end, ChronoUnit.MINUTES),
  36.                     now.until(end, ChronoUnit.HOURS)
  37.             );
  38.         }
  39.     }
  40. }

测试

编写一个 controller 来测试

  1. package cn.mrcode.controller.test;
  3. import cn.hutool.core.date.DatePattern;
  4. import cn.hutool.core.date.DateUtil;
  5. import cn.hutool.core.util.RandomUtil;
  6. import cn.mrcode.timewatch.TimeWatch;
  7. import lombok.extern.slf4j.Slf4j;
  8. import org.springframework.beans.factory.annotation.Autowired;
  9. import org.springframework.web.bind.annotation.GetMapping;
  10. import org.springframework.web.bind.annotation.RequestMapping;
  11. import org.springframework.web.bind.annotation.RestController;
  13. import java.util.Date;
  14. import java.util.concurrent.TimeUnit;
  17. @RequestMapping("/test")
  18. @RestController
  19. @Slf4j
  20. public class TestController {
  22.     @TimeWatch("timewatch 切面测试")
  23.     @GetMapping("/timewatch")
  24.     public Result timewatch() throws InterruptedException {
  25.         log.info("开始时间：{}", DateUtil.format(new Date(), DatePattern.NORM_DATETIME_MS_PATTERN));
  26.         long l = System.currentTimeMillis() % 3;
  27.         // 这里只测试 毫秒、秒、分钟
  28.         if (l == 0) {
  29.             int timeout = RandomUtil.randomInt(10, 1000);
  30.             log.info("休眠 {} 毫秒", timeout);
  31.             TimeUnit.MILLISECONDS.sleep(timeout);
  32.         } else if (l == 1) {
  33.             int timeout = RandomUtil.randomInt(10, 50);
  34.             log.info("休眠 {} 秒", timeout);
  35.             TimeUnit.SECONDS.sleep(timeout);
  36.         } else if (l == 2) {
  37.             int timeout = RandomUtil.randomInt(1, 3);
  38.             log.info("休眠 {} 分钟", timeout);
  39.             TimeUnit.MINUTES.sleep(timeout);
  40.         }
  41.         log.info("结束时间：{}", DateUtil.format(new Date(), DatePattern.NORM_DATETIME_MS_PATTERN));
  42.         return ResultHelper.ok("ok");
  43.     }
  44. }

访问链接： GET localhost/test/timewatch

  1. 由于写的按照当前时间去休眠单位，所以需要多测试几下才能看到 毫秒、秒、分钟的测试信息
  3. // 毫秒测试信息
  4. 2022-08-04 10:33:17.664  INFO 10620 --- [io-11140-exec-1] c.r.d.d.w.c.test.TestController          : 开始时间：2022-08-04 10:33:17.659
  5. 2022-08-04 10:33:17.665  INFO 10620 --- [io-11140-exec-1] c.r.d.d.w.c.test.TestController          : 休眠 581 毫秒
  6. 2022-08-04 10:33:18.246  INFO 10620 --- [io-11140-exec-1] c.r.d.d.w.c.test.TestController          : 结束时间：2022-08-04 10:33:18.246
  7. 2022-08-04 10:33:18.249  INFO 10620 --- [io-11140-exec-1] c.r.d.d.c.timewatch.TimeWatchAspect      : [timewatch 切面测试] 耗时:590 毫秒 | 0 秒 | 0 分钟 | 0 小时
  9. // 秒测试信息
  10. 2022-08-04 10:35:27.391  INFO 10620 --- [io-11140-exec-3] c.r.d.d.w.c.test.TestController          : 开始时间：2022-08-04 10:35:27.391
  11. 2022-08-04 10:35:27.391  INFO 10620 --- [io-11140-exec-3] c.r.d.d.w.c.test.TestController          : 休眠 35 秒
  12. 2022-08-04 10:36:02.392  INFO 10620 --- [io-11140-exec-3] c.r.d.d.w.c.test.TestController          : 结束时间：2022-08-04 10:36:02.392
  13. 2022-08-04 10:36:02.394  INFO 10620 --- [io-11140-exec-3] c.r.d.d.c.timewatch.TimeWatchAspect      : [timewatch 切面测试] 耗时:35003 毫秒 | 35 秒 | 0 分钟 | 0 小时
  15. // 分钟信息就不测试了

资料扩展

本文所用到的知识点来自如下文章：