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

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