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 配置示例
bind-to="longMethod"/> bind-to="longMethod"/>
清单 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 6Fibo[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 fiboEntering method fiboEntering method fiboEntering method fiboEntering method fiboLeaving method fiboEntering method fiboLeaving method fiboLeaving method fiboEntering method fiboLeaving method fiboLeaving method fiboEntering method fiboEntering method fiboLeaving method fiboEntering method fiboLeaving method fiboLeaving method fiboLeaving method fiboEntering method fiboEntering method fiboEntering method fiboLeaving method fiboEntering method fiboLeaving method fiboLeaving method fiboEntering method fiboLeaving method fiboLeaving method fiboLeaving method fiboFibo[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 元素， 改变的地方用粗体标出：
bind-to="longMethod"/>
清单 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<3Leaving method fibo<8Fibo[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 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
想像力比知识更重要
