Spring AOP 切面編程記錄日志和接口執行時間

最近客戶現在提出系統訪問非常慢，需要優化提升訪問速度，在排查了nginx、tomcat內存和服務器負載之后，判斷是數據庫查詢速度慢，進一步排查發現是因為部分視圖和表查詢特別慢導致了整個系統的響應時間特別長。知道了問題之后，就需要對查詢比較慢的接口進行優化，但哪些接口需要優化、哪些不需要呢？只能通過日志里的執行時間來判斷，那么如何才能知道每一個接口的執行時間呢？

對於這個問題，想到了使用動態代理的方式統一記錄方法的執行時間並打印日志，這樣就能很直觀、方便的看到每個接口的執行時間了。

由於使用的是spring框架，對象都是由spring統一管理的，所以最后使用的是 Spring AOP 切面編程來統一記錄接口的執行時間，具體代碼如下（基於注解的方式）：

@Component
@Aspect
public class AopLoggerAspect {

    private static final Logger logger = Logger.getLogger(AopLoggerAspect.class);

    @Pointcut("execution(public * com.iflytek.credit.platform.*.service.impl.*Impl.*(..)) || execution(public * com.iflytek.credit.platform.*.controller.*Controller.*(..))")
    public void pointCut() {

    }

    @Before("pointCut()")
    public void boBefore(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP before ");
    }

    @After("pointCut()")
    public void doAfter(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after ");
    }

    @AfterReturning(pointcut = "pointCut()",returning = "result")
    public void afterReturn(JoinPoint joinPoint, Object result) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after return ,and result is : " + result.toString());
    }

    @AfterThrowing(pointcut = "pointCut()",throwing = "throwable")
    public void afterThrowing(JoinPoint joinPoint, Throwable throwable) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after throwing ,and throwable message is : " + throwable.getMessage());
    }

    @Around("pointCut()")
    public Object around(ProceedingJoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        try {
            logger.info("Method Name : [" + methodName + "] ---> AOP around start");
            long startTimeMillis = System.currentTimeMillis();
            //調用 proceed() 方法才會真正的執行實際被代理的方法
            Object result = joinPoint.proceed();
            long execTimeMillis = System.currentTimeMillis() - startTimeMillis;
            logger.info("Method Name : [" + methodName + "] ---> AOP method exec time millis : " + execTimeMillis);
            logger.info("Method Name : [" + methodName + "] ---> AOP around end , and result is : " + result.toString());
            return result;
        } catch (Throwable te) {
            logger.error(te.getMessage(),te);
            throw new RuntimeException(te.getMessage());
        }
    }

}

 

首先，需要創建一個類，然后在類名上加上兩個注解

@Component
@Aspect

@Component 注解是讓這個類被spring當作一個bean管理，@Aspect 注解是標明這個類是一個切面對象

類里面每個方法的注解含義如下：

@Pointcut  用於定義切面的匹配規則，如果想要同事匹配多個的話，可以使用 || 把兩個規則連接起來，具體可以參照上面的代碼

@Before  目標方法執行前調用

@After  目標方法執行后調用

@AfterReturning  目標方法執行后調用，可以拿到返回結果，執行順序在 @After 之后

@AfterThrowing  目標方法執行異常時調用

@Around  調用實際的目標方法，可以在目標方法調用前做一些操作，也可以在目標方法調用后做一些操作。使用場景有：事物管理、權限控制，日志打印、性能分析等等

以上就是各個注解的含義和作用，重點的兩個注解就是 @Pointcut 和 @Around 注解，@Pointcut用來指定切面規則，決定哪些地方使用這個切面；@Around 會實際的去調用目標方法，這樣就可以在目標方法的調用前后做一些處理，例如事物、權限、日志等等。

需要注意的是，這些方法的執行順序：

執行目標方法前： 先進入 around ，再進入 before 
目標方法執行完成后： 先進入 around ，再進入 after ，最后進入 afterreturning 

實際的日志信息如下，可以看出各個方法的執行順序：

 

另外，使用spring aop 需要在spring的配置文件加上以下這行配置，以開啟aop ：

<aop:aspectj-autoproxy/>

同時，maven中需要加入依賴的jar包：

<dependency>
   <groupId>org.aspectj</groupId>
   <artifactId>aspectjrt</artifactId>
   <version>1.6.12</version>
</dependency>
<dependency>
   <groupId>org.aspectj</groupId>
   <artifactId>aspectjweaver</artifactId>
   <version>1.6.12</version>
</dependency>

總結一下，Spring AOP 其實就是使用動態代理來對切面層進行統一的處理，動態代理的方式有：JDK動態代理和 cglib 動態代理，JDK動態代理基於接口實現， cglib 動態代理基於子類實現。spring默認使用的是JDK動態代理，如果沒有接口，spring會自動的使用cglib動態代理。

 

參考：

https://www.cnblogs.com/liuruowang/p/5711563.html

https://www.cnblogs.com/parryyang/p/5881523.html

（兩篇都是比較好的文章，在此感謝作者）