使用AOP與注解記錄Java日志
有些時候,我想要把每個運行過的方法接收到的參數、返回值和執行時間等信息記錄(通過slf4j 和 log4j)下來。在AspectJ、jcabi-aspects和Java注解的幫助下我實現了這個想法。
public class Foo { @Loggable public int power(int x, int p) { return Math.pow(x, p); } }
在log4j中可以看到以下輸出:
[INFO] com.example.Foo #power(2, 10): 1024 in 12μs [INFO] com.example.Foo #power(3, 3): 27 in 4μs
看上去很酷對吧?接下來我們來看看它是如何工作的。
注解
注解是Java 6中采用的一種技術(譯注:其實Java 5就有注解了)。它是一種不會影響程序運行的元編程指令,我們可以用它來對一些指定的元素(方法、類或者變量)進行標記。換句話說,注解就是代碼中可以看到的標記。一些注解只在編譯階段可見——它們不存在于編譯好的.class文件中,另外一些注解在編譯后仍然可見。
例如,@Override是第一種類型(它的保留類型是SOURCE),而JUnit的@Test是第二種類型(保留類型是RUNTIME),@Loggable——我在上面使用過的是第二種注解,包含在jcabi-aspects中,在編譯后會留在.class文件中。
值得注意的是,上文的power()方法即便被注解并且編譯,也不會發送任何內容到slf4j。僅僅是一種用來提醒相關軟件“請記錄我的執行過程”的標記, 理解這一點很重要。
AOP
AOP(面向切面編程)是一種可以在對源代碼不作明顯改動的情況下向其加入可執行塊的技術。在上面的示例中,我們不想在實現類中記錄方法的執行,而是用其他類去攔截power()方法的每次調用,測量執行時間并把這些信息發送給slf4j。
我想要使攔截類能識別@Loggable注解并且記錄下power()方法的每次調用,當然它也應該能攔截其他方法。
這個想法與AOP的出發點很符合——避免在多個類中重復實現一些共同的功能。
日志是Java主要功能的一個補充。我們不想往代碼中加入繁雜的日志指令,這樣會導致代碼可讀性降低,所以我們想在別的地方偷偷地記錄日志。
從AOP的角度來看,我們的解決方案是新建一個指定切入點和環繞通知的切面以實現預期的功能。
AspectJ
接下來,讓我們來看看這些神奇的注解。首先,讓我們來了解jcabi-aspects是如何用AspectJ來實現注解的。下面是一個簡單例子,你可以在MethodLogger.java中找到全部代碼。
@Aspect public class MethodLogger { @Around("execution(* *(..)) && @annotation(Loggable)") public Object around(ProceedingJoinPoint point) { long start = System.currentTimeMillis(); Object result = point.proceed(); Logger.info( "#%s(%s): %s in %[msec]s", MethodSignature.class.cast(point.getSignature()).getMethod().getName(), point.getArgs(), result, System.currentTimeMillis() - start ); return result; } }
這個切面(aspect)里有一個around()通知,切面用@Aspect注解,通知用@Around注解, 上面提到過這些注解僅僅是在.class文件中做了標記,這些標記在運行時能提供一些信息給那些對它們感興趣對象。
@Around注解有一個參數,如果該方法
- 可見性是 * (public、protected或private);
- 名字是 * (任何名字都可以);
- 參數是 .. (任何參數都可以);
- 注解為@Loggable
那么通知就會應用到該方法。
當注解方法被調用的時就會被攔截,around()通知會在被攔截方法之前執行,其中 @Around 類型的通知需要一個 ProceedingJoinPoint 類的實例作為參數,之后返回一個對象給power()方法。
為了調用power()方法,通知需要調用join point對象的proceed()方法。
接下來編譯并把它加入環境變量,讓我們的主文件Foo.class能夠調用它。目前為止一切順利,我們還需要最后一步——把通知運轉起來。
二進制切面織入
切面織入(aspect waving)就是將切面應用到目標對象從而創建一個新的代理對象的過程。切面織入將一些代碼插入原代碼,AspectJ就是這么做的。我們給它兩個二進制Java類Foo.class 和 MethodLogger.class; 它返回三個類——修改過的Foo.class、Foo$AjcClosure1.class和未修改的MethodLogger.class。
為了理解如何將不同的通知應用于對應的哪個方法,AspectJ織入在.class文件中使用了注解,并使用反射來瀏覽環境變量中的所有類。它分析@Around注解中的哪個方法滿足條件。power()就在此時被發現了。
上述操作需要分為兩步。首先,我們把.java文件編譯。然后AspectJ對編譯后的文件進行織入/修改,織入后的Foo類看起來像下面這樣:
public class Foo { private final MethodLogger logger; @Loggable public int power(int x, int p) { return this.logger.around(point); } private int power_aroundBody(int x, int p) { return Math.pow(x, p); } }
AspectJ織入把我們原來的功能移到新方法power_aroundBody()中,并把所有的power()調用重定向到切面類MethodLogger。
下圖是每次調用power()的過程:

圖中那一小塊綠色就是原方法power()。
如你所見,切面織入過程把類和切面等聯系起來了。如果沒有織入,它們僅僅是一堆編譯好的二進制代碼和注解。
jcabi-aspects
jcabi-aspects是一個含有Loggable注解和MethodLogger切面的JAR庫,它還有其它注解和切面。你不必自己實現切面,只要在環境變量加入一些依賴并為切面織入配置好jcabi-maven-plugin。可以到Maven Central獲取最新版本。
<project> <depenencies> <dependency> <dependency> <groupId>com.jcabi</groupId> <artifactId>jcabi-aspects</artifactId> </dependency> <dependency> <groupId>org.aspectj</groupId> <artifactId>aspectjrt</artifactId> </dependency> </dependency> </depenencies> <build> <plugins> <plugin> <groupId>com.jcabi</groupId> <artifactId>jcabi-maven-plugin</artifactId> <executions> <execution> <goals> <goal>ajc</goal> </goals> </execution> </executions> </plugin> </plugins> </build> </project>
由于織入過程比較復雜,我用Maven插件和ajc goal做了一個便捷的織入。你也可以直接用AspectJ,不過我還是推薦你使用jcabi-maven-plugin。
好了,現在你可以用@com.jcabi.aspects.Loggable 注解你的方法執行過程將會通過slf4j記錄下來。
如果按上述操作沒有得到預期效果,歡迎到Github issue提出問題。
原文鏈接: javacodegeeks 翻譯: ImportNew.com - 李 廣
譯文鏈接: http://www.importnew.com/13367.html