基於AspectJ加強代碼，實現一行註解記錄方法執行耗時

背景

因須要對項目中的方法執行進行性能測試，若是在每一個方法先後都加上以下代碼

long beginTime = System.currentTimeMillis(); 
long endTime = System.currentTimeMillis(); 
long timeConsume = endTime - beginTime; 
複製代碼

顯然會讓代碼變得很是冗雜，並且須要統計性能的地方可能還會有不少，若是能夠單純在方法上加上一個註解，就能實現方法執行耗時的記錄，這樣便能減小許多簡單且繁瑣的代碼，更加方便的擴展

技術選型

像這種場景就是典型的AOP場景，搜索SpringAOP就能找到不少的代碼樣例，可是項目並不依賴於Spring， 也沒有必要引入Spring。一般要實現這樣的功能，有兩種方案，一種是像SpringAOP那樣，經過CGLib動態代理或JDK動態代理，在建立對象的時候，動態地生成代理類的對象，另外一種是AspectJ，在編譯代碼的時候就將須要執行的邏輯織入到字節碼中。

對於動態代理，須要建立代理類的對象，才能夠加強，而項目中，存在不少靜態方法，在使用的時候並不經過對象來調用，並且即使是經過對象來調用的方法，沒有Spring方便的IOC機制，也得修改全部代碼中new對象的處理，纔可使用加強後的代理對象，略麻煩。並且若是是頻繁的建立對象，由於還有一步建立代理對象的操做，性能上會有必定的損失。

對於AspectJ這種方式，則能夠對知足切點表達式的地方，都織入加強後的邏輯，可是須要依賴於織入工具的協助，來對編譯後的字節碼進行加強。幸虧maven上已經有對應的aspectj編譯插件，能夠很方便的處理織入

綜合考慮之下，決定採用自定義註解（指定目標）+ ApsectJ(Aop加強) + aspectj的Maven編譯插件來實現

技術實現

一、自定義註解

@Retention(RetentionPolicy.RUNTIME) 
@Target(ElementType.METHOD) 
public @interface TimeConsumeLogAnnotation { 

} 
複製代碼

二、引入Aspectj依賴

<dependency> 
​    <groupId>org.aspectj</groupId> 
​    <artifactId>aspectjrt</artifactId> 
​    <version>1.8.9</version> 
</dependency> 
複製代碼

三、Aspectj切面

@Aspect 
public class TimeConsumeLogAspectJ { 
​    //經過ThreadLocal隔離不一樣線程的變量 
​    ThreadLocal<Long> timeRecord = new ThreadLocal<>(); 

​    @Pointcut("execution(* *(..)) && @annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
​    public void jointPoint(){} 

​    @Before("jointPoint()") 
​    public void doBefore(JoinPoint joinPoint){ 
​        MethodSignature signature = (MethodSignature) joinPoint.getSignature(); 
​        Method method = signature.getMethod(); 
​        System.out.println("方法" + method.getName() + "開始"); 
​        timeRecord.set(System.currentTimeMillis()); 
​    } 

​    @After("jointPoint()") 
​    public void doAfter(JoinPoint joinPoint){ 
​        long beginTime = timeRecord.get(); 
​        System.out.println("方法" +joinPoint.getSignature().getName()+ "結束,耗時"+(System.currentTimeMillis()-beginTime) +"ms"); 
​    } 
} 
複製代碼

四、引入maven編譯插件

在maven-compiler-plugin處理完以後再工做

<plugin> 
​    <groupId>org.codehaus.mojo</groupId> 
​    <artifactId>aspectj-maven-plugin</artifactId> 
​    <version>1.10</version> 
​    <configuration> 
​        <source>1.8</source> 
​        <target>1.8</target> 
​        <complianceLevel>1.8</complianceLevel> 
​    </configuration> 
​    <executions> 
​        <execution> 
​            <phase>compile</phase> 
​            <goals> 
​                <goal>compile</goal> 
​            </goals> 
​        </execution> 
​    </executions> 
</plugin> 
複製代碼

五、在目標方法上加入@TimeConsumeLogAnnotation註解編譯運行便可

@TimeConsumeLogAnnotation() 
public static void sayHelloWorld(String name) { 
​    System.out.println("Hello " + name); 
} 
複製代碼

編譯後的字節碼

@TimeConsumeLogAnnotation 
public static void sayHelloWorld(String name) { 
​    JoinPoint var1 = Factory.makeJP(ajc$tjp_0, (Object)null, (Object)null, name); 
​    try { 
​        TimeConsumeLogAspectJ.aspectOf().doBefore(var1); 
​        System.out.println("Hello " + name); 
​    } catch (Throwable var4) { 
​        TimeConsumeLogAspectJ.aspectOf().doAfter(var1); 
​        throw var4; 
​    } 
​    TimeConsumeLogAspectJ.aspectOf().doAfter(var1); 
} 
複製代碼

效果

方法sayHelloWorld開始 
Hello world 
方法sayHelloWorld結束,耗時1ms 
複製代碼

六、踩過的坑

（1）切面執行兩次

在一開始切面的表達式爲

@Pointcut("@annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
複製代碼

而aspectj的編譯器會識別出方法調用和方法執行兩個階段的切入點，由於會在這兩個階段都執行

經過將切面表達式修改成

@Pointcut("execution(* *(..)) && @annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
複製代碼

能夠限定成只識別方法執行這個階段

（2）多模塊項目aspectj編譯失敗

若是在多模塊項目，在具體的某個子模塊聲明切面類，定義切點表達式，可是鏈接點切分散在各個其餘模塊時，ajc掃描具到切點表達式時，只會在本模塊掃描對應的鏈接點，其餘模塊的鏈接點是沒有辦法編繹期切入切面，ajc是不會在編繹其餘模塊時再去掃描有沒有某個切點表達式與當前鏈接點匹配的

經過在每一個模塊都加上自定義註解和切面，可解決編譯的問題

更多的操做

因爲自定義註解支持賦值，Aspectj切面又能夠攔截到方法，而且經過反射獲取到方法參數，所以能夠在這基礎作更多定製化的優化

參考連接

Spring AOP 實現原理與 CGLIB 應用

關於AspectJ你可能不知道的事

AspectJ切面執行兩次緣由分析

多模塊maven項目使用Eclipse的 AspectJ編繹期織入