Programming Design Notes

有時為了改善系統效能，需要知道那一個程序用了較多時間，而每一個程序又會用到很多不同的 Method 去完成，如果每一個 Method 也要記錄執行時間，而 Method 數目又有很多，不可能在每一個 Method 前加上 Timer 後面記錄 Timer 時間，這時候 AspectJ 便大派用場了。

這篇文章是 Spring + AspectJ，不是單純使用 AspectJ，所以要記錄執行時間的 Method 必須是 Spring bean，非 Spring 管理的 bean 是記錄不到的。

首先是在設定 bean 的 xml 檔案加上以下內容:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:p="http://www.springframework.org/schema/p"
    xmlns:context="http://www.springframework.org/schema/context"
 xmlns:aop="http://www.springframework.org/schema/aop"
    xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
 http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context.xsd
 http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-3.0.xsd">
 
    <aop:aspectj-autoproxy />
    <context:component-scan base-package="com.ctlok.pro.bean.aspect" />

</beans>

我是使用註解的方式去設定 Spring bean 的，如果你不是使用這種方式請自行更改。
現在制作記錄執行時間的 bean。

package com.ctlok.pro.bean.aspect;

import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class ProcessTimeLogger {

}

在這裡 AspectJ 也是使用註解的方式去設定，加上 @Component 是要令 Spring Loader 也將這個 POJO 載入成 Spring bean。

要記錄時間當然也要使用 Logger 去記錄，而且要令 AspectJ 知道記錄那一此 Method，請加上以下內容:

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

@Pointcut("execution(* com.ctlok.pro.bean.service.*.*(..))")
public void service(){}

在這裡我使用 java.util.logging.Logger 去記錄時間，你喜歡可以改為 log4j 或 slf4j 也可以。

@Pointcut 這個註解是用來設定在程式那一倨位置設入。

* com.ctlok.pro.bean.service.*.*(..) 的第一顆 * 是 public、 protected、 privat 或預設 method，如果你

只想記錄 public method，可以改成以下這樣:

@Pointcut("execution(public com.ctlok.pro.bean.service.*.*(..))")
public void service(){}

而 service.*.*(..) 第一顆 * 是代表 class，因為我的 Spring bean 也放在 service 目錄下，而第二顆是代表 Method 名稱，(..) 即是這個 Method 有變數輸入或是沒有變數輸入都可以。

而在可以新增一個 Method 去記錄時間，輸入以下內容:

@Around("service()")
public Object logging(ProceedingJoinPoint joinPoint) throws Throwable{
    String clazz = joinPoint.getTarget().getClass().getSimpleName();  
    String method = joinPoint.getSignature().getName(); 
    StopWatch watch = new StopWatch(); 
    watch.start();
    Object result = joinPoint.proceed();
    watch.stop();   
    String log = clazz + " Run " + method + "method complete in " + watch.getTime() + " ms";
    logger.info(log);   
    return result;
}

@Around 可以用來設定在 Method 執行前後所做的動作。

ProceedingJoinPoint joinPoint 可以用來提取一些資訊，AspectJ 會自動將變數傳。

joinPoint.getTarget() 則可以取得現在將會執行的 Method 的 Class。

joinPoint.getSignature() 可以取得現在將會執行的 Method 名稱。

StopWatch 是一個 Timer，在 Method 執行前開始記錄時間。

joinPoint.proceed() 用來執行 Method。

最後便是記錄執行時間了。

完整的 ProcessTimeLogger:

package com.ctlok.pro.bean.aspect;

import java.util.logging.Logger;

import org.apache.commons.lang.time.StopWatch;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class ProcessTimeLogger {

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

    @Pointcut("execution(* com.ctlok.pro.bean.service.*.*(..))")
    public void service() {
    }

    @Around("service()")
    public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
        String clazz = joinPoint.getTarget().getClass().getSimpleName();
        String method = joinPoint.getSignature().getName();
        StopWatch watch = new StopWatch();
        watch.start();
        Object result = joinPoint.proceed();
        watch.stop();
        String log = clazz + " Run " + method + "method complete in "
                + watch.getTime() + " ms";
        logger.info(log);
        return result;
    }
}

在這裡有一點要注意，如果 A method 會使用到 B method 和 C method，那 A method 的執行時間一定是 B method 和 C method 執行時間總和再加 A method 的執行時間。

現在可以去測試一下那一個 Method 用了比預期多的時間去完成任務。

相關書籍: