aspect 可以清除代碼污染嗎？使用 AspectWerkz 框架進行日志記錄是第一步
簡介：面向方面編程（Aspect-oriented programming，AOP）通過將在應用程序范圍內起作用的功能 分離出來而不是放到某個類或者包中，可以使代碼保持清潔。日志記錄是這種功能的一個常用的例子。 AOP 是否可以幫助進行日志記錄？在本文中，開發人員和 AOP 擁護者 Dennis Sosnoski 對 AspectWerkz 框架的使用進行分析以找出答案。
在我的關於 Java 編程動態性 的文章中，展示了如何用 classworking 技術實現對程序行為的系統改 變。這種方法是 Java 平台上用面向對象編程（AOP）進行的大多數工作的基礎。在本文中，我將展示如 何用 AOP 框架在 classworking 之上構建更高層次以實現同樣的系統改變，從而提高使用的方便性。
AspectWerkz 介紹
Java 平台有許多 AOP 框架。在本系列文章中，我選擇使用 AspectWerkz 框架，這是一個由 BEA Systems 贊助的開放源代碼項目。AspectWerkz 不是針對 Java 技術的最早的 AOP —— 這項榮譽屬於 IBM 支持的 Java 編程語言的 AspectJ 擴展 —— 但是作為一種快速、強大且靈活的，與標准 Java 代 碼結合的 AOP 框架，AspectWerkz 獲得了越來越多的關注。AspectWerkz 和 AspectJ 團隊最近宣布合並 他們的工作，所以未來我們將會看到這兩種 Java 編程的 AOP 方法的最好的特性結合到一個產品中。我 將在本專欄中跟蹤這一點，但是現在我將堅持使用基本的 AspectWerkz 框架。
注意： 不要錯過新的 AOP@Work 專欄，它對 AOP 的實際使用做了很好的介紹。它開始於 2005 年 2 月，由五位重要的 AOP 專家執筆，這個為期一年的系列中的每一篇文章都會提供可以立即加以應用的知 識。
當 AOP 支持者列出日常開發的 AOP 應用程序時，似乎總是用到了日志記錄。在典型企業應用程序代 碼的很大部分中都會使用日志記錄，顯然這是需要關注的內容。日志記錄代碼與應用程序的主要目的無關 ，並且它還有可能對代碼產生很大干擾。這些特點結合在一起使得日志記錄成為構建 aspect 的很好候選 對象。我將分析一個實現日志記錄和性能度量相結合的 aspect，以觀察將 aspect 范式應用到這種類型 的問題的情況。
AspectWerkz 基礎
AspectWerkz 網站提供了大量文檔和使用示例，以及關於使用 AspectWerkz 的文章的鏈接。我不准備 在這裡重復這些內容，但是我將簡要介紹我認為最重要的概念：pointcut、aspect 和 advice。
pointcut 基本上只是一個中斷應用程序執行的（由源代碼定義的）“正常” 流程並做一些不同的事 情的地方。AspectWerkz 支持與 Java 代碼結構相關的許多類型的 pointcut，包括方法調用或者執行、 字段 get/set 和異常處理器執行，以及組合（包括特定執行路徑中的代碼）。
用 AspectWerkz 術語來說，一個 aspect 就是一個 Java 類，它可以作為交叉關注（crosscutting concern）的目標。讓一個類成為 aspect 不需要實現特殊的接口，但是需要特定的方法簽名以使類作為 一個 aspect 被訪問。一般來說，希望 aspect 類在標准應用程序類層次結構之外，因為可能只是通過 AspectWerkz 框架使用它們，不過，對於它們所在的位置同樣沒有特殊要求（在運行時類路徑中除外）。
advice 是 aspect 類中的一個方法，在 pointcut 處用它來做“某些不同的事件”。 advice 的默認 方法簽名接受一個參數，該參數提供關於中斷的 pointcut 的信息。清單 1 顯示了一個 aspect 類的例 子，它定義了在方法調用上，將被用作前 advice 和後 advice 的兩個方法。
清單 1. 一個簡單的 advice 類及其 advice 方法
package com.sosnoski.aspectwerkz;
public class TraceAspect
{
public void beforeMethod(JoinPoint join) {
System.out.println("Entering method");
}
public void afterMethod(JoinPoint join) {
System.out.println("Leaving method");
}
}
AspectWerkz 還支持其他方法調用簽名，不過需要多做一些配置工作。談到配置， 有一件事要事先說 明。AspectWerkz 支持三種配置形式：
嵌入到源代碼的 Java 5.0 annotation。
嵌入到源代碼中的、Javadoc 形式的 annotation。
一個外部 XML 文件。
我自己作為一名習慣使用 XML 的人，我將在本文中使用 XML 這種方法。清單 2 顯示了清單 1 中的 advice 的一個示例 XML 配置。
清單 2. XML 配置示例
<aspectwerkz>
<system id="AspectWerkzExample">
<package name="com.sosnoski.aspectwerkz">
<aspect class="TraceAspect">
<pointcut name="longMethod"
expression="execution(long ..(..))"/>
<advice name="beforeMethod" type="before"
bind-to="longMethod"/>
<advice name="afterMethod" type="after"
bind-to="longMethod"/>
</aspect>
</package>
</system>
</aspectwerkz>
清單 2 的配置定義了一個 aspect，如在類 com.sosnoski.aspectwerkz.TraceAspect 中所實現的。 對於這個 aspect，它定義了一個 pointcut，表示任何返回一個 long 值的方法的執行（表達式中需要匹 配的“..”序列是通配符），並在這個 pointcut 上綁定兩個單獨的 advice。第一個 advice 是由 advice 類中的 beforeMethod() 實現的，類型為 before （表明這個 advice 方法將在執行 pointcut 方法之前執行）。第二個 advice 是由 afterMethod() 實現的，類型為 after（因此這個 advice 方法 將在執行了 pointcut 方法之後調用）。
日志
我已介紹了 AspectWerkz 的基本概念，那麼如何將這些概念應用到日志記錄功能呢？上一節中的方法 調用例子應該是一個很好的起點。如果可以配置 AspectWerkz 在每次需要關注的方法調用之前和之後， 分別執行 beforeMethod() 和 afterMethod()，那麼它們會提供應用程序執行的有用蹤跡。
當然，要使執行蹤跡有用，需要對 清單 1 的方法給出的最小信息輸出進行擴展。幸運的是， AspectWerkz 提供了訪問中斷的 pointcut 的信息的方便方法。清單 3 中的代碼展示了如何訪問 pointcut 中的實際方法信息。
清單 3. 報告被中斷的方法的 Advice 方法
package com.sosnoski.aspectwerkz;
public class TraceAspect
{
public void beforeMethod(JoinPoint join) {
MethodSignature signature =
(MethodSignature)join.getSignature();
System.out.println("Entering method " +
signature.getName());
}
public void afterMethod(JoinPoint join) {
MethodSignature signature =
(MethodSignature)join.getSignature();
System.out.println("Leaving method " +
signature.getName());
}
}
為了測試這段初步的日志記錄代碼，我將使用一個精巧的遞歸方法，它是斐波納契數列計算的一個實 現，如清單 4 所示。
清單 4. 斐波納契數列計算
package com.sosnoski.aspectwerkz;
public class FiboTest
{
private long fibo(int value) {
if (value > 2) {
return fibo(value-1) + fibo(value-2);
} else {
return 1;
}
}
public static void main(String[] args) {
FiboTest inst = new FiboTest();
int value = Integer.parseInt(args[0]);
System.out.println("Fibo[" + value + "] is " +
inst.fibo(value));
}
}
直接運行這段代碼很簡單：
[dms]$ java -cp classes com.sosnoski.aspectwerkz.FiboTest 6
Fibo[6] is 8
用 AspectWerkz 運行它要復雜一些。有兩種用 AspectWerkz 實現 aspect 處理的方法： 編譯時類修 改和運行時類修改。在本文中，我將使用運行時方法。這種方法需要一個作為 AspectWerkz 框架一部分 提供的客戶類裝載器。為 AspectWerkz 安裝主目錄建立一個環境變量，並假定 XML 配置（見 清單 2） 是在 aspectwerkz.xml 文件中，下面是使用 AspectWerkz 的 清單 4 的 Linux 和 UNIX 版本（命令行 加了換行以適合本文的寬度限制）：
[dms]$ $ASPECTWERKZ_HOME/bin/aspectwerkz
-Daspectwerkz.definition.file=aspectwerkz.xml
-cp classes com.sosnoski.aspectwerkz.FiboTest 6
得到的輸出也要長得多。在這裡和在其他的例子中，我將忽略由 AspectWerkz 打印的啟動信息，並顯 示由我的 advice 生成的輸出。輸出如清單 5 所示：
清單 5. 修改後的計算結果
Entering method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Entering method fibo
Entering method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Entering method fibo
Leaving method fibo
Leaving method fibo
Leaving method fibo
Fibo[6] is 8
加以改進
清單 5 顯示調用了 清單 3 中的 advice 方法， 但是沒有提供關於所執行的應用程序的很多有用信 息。通過修改這個 advice 以縮進方式顯示嵌套的方法調用，並且打印傳遞和返回的值，我將改進這一不 足。為此，我還要將這個 advice 改為另一種類型：around advice 類型。清單 6 顯示了修改後的代碼 。
清單 6. 帶有縮進和值打印的 advice 方法
private int m_nestingDepth;
private void indent() {
for (int i = 0; i < m_nestingDepth; i++) {
System.out.print(' ');
}
}
private void printCall(JoinPoint call) {
MethodSignature signature =
(MethodSignature)call.getSignature();
System.out.print(signature.getName());
System.out.print('(');
MethodRtti rtti = (MethodRtti)call.getRtti();
System.out.print(rtti.getParameterValues()[0]);
System.out.print(')');
}
public Object traceLong(JoinPoint join) throws Throwable {
// print entering information
indent();
System.out.print("Entering method ");
printCall(join);
// execute the joinpoint method
m_nestingDepth++;
Object result = join.proceed();
m_nestingDepth--;
// print exiting information
indent();
System.out.print("Leaving method ");
MethodSignature signature =
(MethodSignature)join.getSignature();
System.out.print(signature.getName());
System.out.print('<');
System.out.println(result);
// return result from method call
return result;
}
從名字上可以看出，around advice 包圍了 pointcut 執行。當要執行 pointcut 時調用它，並且具 有決定什麼時候執行 —— 甚至是否執行 —— pointcut 的靈活性。在清單 6 的代碼中，我盡量使 around advice 的處理簡單化。在這裡，advice 代碼（traceLong() 方法）首先在當前縮進位置打印方 法名和參數值。然後調用方法並保存結果，然後在比當前縮進位置再縮進的位置打印方法名和返回值。
需要調整 XML 配置以使用這個新的 advice，但是這種改變很容易。下面是文件中的 aspect 元素， 改變的地方用粗體標出：
<package name="com.sosnoski.aspectwerkz">
<aspect class="TraceAspect">
<pointcut name="longMethod"
expression="execution(long ..(..))"/>
<advice name="traceLong" type="around"
bind-to="longMethod"/>
</aspect>
</package>
清單 7 給出了用這種新的 advice 產生的輸出。
清單 7. 帶縮進和值打印的輸出
Entering method fibo(6)
Entering method fibo(5)
Entering method fibo(4)
Entering method fibo(3)
Entering method fibo(2)
Leaving method fibo<1
Entering method fibo(1)
Leaving method fibo<1
Leaving method fibo<2
Entering method fibo(2)
Leaving method fibo<1
Leaving method fibo<3
Entering method fibo(3)
Entering method fibo(2)
Leaving method fibo<1
Entering method fibo(1)
Leaving method fibo<1
Leaving method fibo<2
Leaving method fibo<5
Entering method fibo(4)
Entering method fibo(3)
Entering method fibo(2)
Leaving method fibo<1
Entering method fibo(1)
Leaving method fibo<1
Leaving method fibo<2
Entering method fibo(2)
Leaving method fibo<1
Leaving method fibo<3
Leaving method fibo<8
Fibo[6] is 8
讓它更靈活
清單 7 的輸出看起來有用一些了，但是缺少選擇性。如果對大的斐波納契數列（比如說 12）使用這 段代碼，將會看到長時間的滾動輸出。作為開發一個有用的日志記錄 aspect 的最後一步，我將實現對輸 出的一些靈活的篩選。
最後我還想做成一個可以用來記錄執行路徑和相關性能度量的 aspect，這樣就可以看到執行時間最長 的方法調用。我使用的方法類似於我在關於 Java 編程動態性的文章中所展示的方法，它基於 java.lang.System.currentTimeMillis() 時間值，使用直接 classworking。 這個計時器不是非常精確 —— 在 Microsoft Windows 上，分辨率約為 17 毫秒，在我的 Linux 系統上，約為 1 毫秒 —— 但是 可以在所有版本的標准 Java 平台上找到它，這使得它至少在展示方面還是有用的。（下個月，我將討論 獲得更好的計時器分辨率。）根據方法調用所花的時間篩選執行蹤跡會得出一些有趣的結果。
為了保持同樣的輸出結構，這個基於時間的篩選要稍微復雜一些。首先，需要延遲打印每個方法調用 的“進入”線（“entering”line），直到可以確定所用的時間足以使它通過我的篩選器。這本身並不困 難，但是我發現 真的 需要打印方法信息時，首先需要打印每一個包圍方法調用的進入線。為此我需要保 持還沒打印的方法的進入信息列表，然後在打印當前方法的進入信息之前將它們都轉儲出來，並帶有正確 的縮進。清單 8 顯示了修改後的新 advice 方法，以使它使用這個未打印的方法列表。
清單 8. 帶時間篩選器的 Advice 方法
private ArrayList m_unprintedCalls = new ArrayList();
private void indent(int depth) {
for (int i = 0; i < depth; i++) {
System.out.print(' ');
}
}
public Object traceTimed(JoinPoint join) throws Throwable {
// add joinpoint to list pending print
m_pendingPrints.add(join);
// time joinpoint execution
long start = System.currentTimeMillis();
m_nestingDepth++;
Object result = join.proceed();
m_nestingDepth--;
// remove joinpoint if still on pending list
// (will always be last in list)
boolean entered = true;
if (m_pendingPrints.size() > 0) {
m_pendingPrints.remove(m_pendingPrints.size()-1);
entered = false;
}
// check if execution time above cutoff
long time = System.currentTimeMillis() - start;
if (time > 1) {
// print all unprinted "entering" lines
int count = m_pendingPrints.size();
for (int i = 0; i < count; i++) {
// print entering information for nesting call
// (nesting depth based on start of pendings)
indent(m_nestingDepth-count+i);
JoinPoint prior =
(JoinPoint)m_pendingPrints.get(i);
System.out.print("Entering ");
printCall(prior);
System.out.println();
}
// clear all pendings now that they're printed
m_pendingPrints.clear();
// print exiting information including time
indent();
System.out.print("Leaving ");
printCall(join);
System.out.print('=');
System.out.print(result);
System.out.print(" took ");
System.out.print(time);
System.out.println(" ms.");
}
// return result from joinpoint execution
return result;
}
修改了 XML 配置文件以在 traceLong() 的地方使用 traceTimed() advice 方法後，用同樣的參數值 “6” 運行它完全不顯示任何蹤跡信息，因為整個執行用時小於最小時間。如果使用值“15”，那麼就得 到清單 9 所示的輸出。
清單 9. 帶時間篩選器的輸出
Entering fibo(15)
Entering fibo(14)
Entering fibo(13)
Entering fibo(12)
Leaving fibo(11)=89 took 2 ms.
Leaving fibo(10)=55 took 2 ms.
Leaving fibo(12)=144 took 11 ms.
Entering fibo(11)
Leaving fibo(10)=55 took 2 ms.
Leaving fibo(9)=34 took 2 ms.
Leaving fibo(11)=89 took 5 ms.
Leaving fibo(13)=233 took 19 ms.
Entering fibo(12)
Leaving fibo(11)=89 took 2 ms.
Entering fibo(10)
Entering fibo(8)
Entering fibo(6)
Leaving fibo(4)=3 took 2 ms.
Leaving fibo(6)=8 took 4 ms.
Leaving fibo(8)=21 took 6 ms.
Leaving fibo(10)=55 took 6 ms.
Leaving fibo(12)=144 took 10 ms.
Leaving fibo(14)=377 took 29 ms.
Entering fibo(13)
Entering fibo(12)
Leaving fibo(11)=89 took 2 ms.
Leaving fibo(10)=55 took 2 ms.
Leaving fibo(12)=144 took 6 ms.
Entering fibo(11)
Leaving fibo(10)=55 took 2 ms.
Leaving fibo(11)=89 took 3 ms.
Leaving fibo(13)=233 took 9 ms.
Leaving fibo(15)=610 took 95 ms.
Fibo[15] is 610
清單 9 輸出正是我想要看到的，因此現在可以拋開斐波納契，轉向真正的應用程序了。我將在下個月 的專欄中做這件事。
結束語
在本次專欄中，介紹了如何用 AspectWerkz 實現帶性能度量增強的基本執行跟蹤。下個月的專欄進一 步拓展這一概念，擴展跟蹤 aspect 並將它應用到復雜的帶有自己的內置日志記錄的真實世界框架上，以 發現 aspect 方法在哪些地方可以很好地發揮作用 —— 在哪些地方不能。aspect 是否可以使我們免於 日志記錄代碼的煩擾？請繼續關注並找出答案。
本文配套源碼：http://www.bianceng.net/java/201212/734.htm
