Classworking 工具箱: 用方面跟踪性能

上个月?我介绍了如何用 AspectWerkz 框架实现一个基本的性能跟踪方面（aspect）。这个月我将进一步发展这个方面， 首先增加一些方便的功能，然后将它用于分析一个复杂的真实世界代码 —— Apache Axis Web 服务框架。您将看到我用这种面向方面的方法进行性能跟踪的好处和局限性，最后我的看法是，进行一般性的日志和跟踪是面向方面编程（AOP）通常可以发挥作用的地方。

在深入 Axis 之前，需要讨论另一个问题。在上个月的性能跟踪方面以及在更早的一篇 关于?Java 编程动态性?的文章中（请参阅?参考资料），我使用了 方法计时信息来分析应用程序性能问题。我个人认为这种方法在某些情况下非常方便，但是， 为了使对它的介绍尽可能地全面，还需要讨论一些副作用的问题。我将在本文的第一部分中讨论这些问题。

清单 2 展示在我的笔记本计算机（有较慢的 1GHz PIIIm，运行 Mandrake Linux 10.0）上用 JDK 1.4.2 运行这个程序的结果。结果显示，在这个例子上，currentTimeMillis()?的时间改变总是一个毫秒，调用这个 方法的开销平均只有 3 毫秒。因为这些值都很一致（在这里是百分之一以内），所以至少 可以合理地假定计时器值是足够精确的。

基本原理仍然与?上个月?一样，但是这段代码 添加了几个警告。除了使用?nanoTime()，我还在方面定义中增加了三个可选配置参数。这些参数控制：

在跟踪输出中加入的方法调用的最小测量时间。输出中的最大嵌套深度。用一个触发器方法打开跟踪，这样，只有这个方法进行的调用（直接或者间接）才会被加入到输出中。

增加的构造函数代码使用 AspectWerkz 2.0 定义的一个签名来访问上下文信息，这些信息包括 为方面定义的所有参数。我将在用到这些参数时，展示如何在 XML 配置文件中定义 它们。

在实际的?trace()?方法开始的地方，我添加了检查触发器方法名与类 匹配的逻辑，如果知道调用不会打印出来，就直接执行 joinpoint 方法调用而不进行计时 （由于触发器方法不在调用的当前嵌套中，或者由于我们已经深入到嵌套中我们不感兴趣的地方）。 我还在基本计时代码中增加了一个 throwable 处理，这样，当方法由于一个抛出而退出而不是正常返回时， 在跟踪中就会加入基本抛出信息。

最后，我改变了跟踪输出的格式以使它更具可读性。这段代码不用空格缩进，而用连字号代替空格， 当方法调用是在嵌套的最深层时，它将在前面打印出星号而不是用于显示从嵌套级中退出的小于号（<）。

Linux 上的 AspectWerkz


我在 Linux 上运行 AspectWerkz 确实遇到过几个奇怪的小问题。首先，提供的 shell 脚本 在我的系统上不运行，因为它们使用 DOS 格式的行结束。我改了行结束后，它们可以在 1.0 和 2.0 RCX 版本上工作，但是不能工作在 1.1 上（我在这里不深究这个问题）。 希望这个问题在 2.0 版本时能修复。

其次，我遇到了 AspectWerkz 1.0 与 2.0 RC3 之间的兼容性问题，这看来是特定于 Linux 的，它使我在使用 AspectWerkz 2.0 时，不得不在 classpath 中加入 Axis 所引用 的所有 JAR 文件，即使其中一些 JAR（包括 Servlet API 定义）通常在客户机上是不需要的。 AspectWerkz 开发人员在 Windows 上再现不了这个问题，但是如果在 Linux 上使用 AspectWerkz 2.0，那么您可能也会遇到同样的问题。












上个月?文章的读者应当熟悉清单 5 配置中的大部分内容。所使用的配置的主要区别是我使用了更复杂的表达式来定义我的方面的切入点，并且增加了一个参数值来定义最大嵌套深度。在我以前的配置中， 使用了?pointcut?元素的属性来定义这个表达式，使用更长的 表达式可以更容易地使它成为元素的内容。AspectWerkz 允许互换地使用这两种形式。 切入点表达式表明我希望在?org.apache.axis?和?com.sosnoski.seismic?层次结构中加入包中的所有类中的所有方法调用。

在测试 Axis 时，我通常多次穿越（请求-响应交换）代码，这样，第一次穿越将处理 初始化，而后面的穿越就可以全速运行。在用性能跟踪方面测试时，我只使用两次穿越， 并且我将只显示第二次穿越的输出。清单 6 给出了使用?清单 5?配置 时，通过 AspectWerkz 运行这个程序的输出。注意，即使使用?nanoTime()?进行计时， 我还是将所有时间值转换为毫秒以保证数字大小适合于打印。


清单 6.初步观察性能跟踪



清单 7 配置保留了与以前一样的切入点定义，但是为方面增加了 一个触发器方法，并将最大嵌套深度减小到 5。清单 8 给出了这个跟踪配置 生成的输出（不带客户机程序输出，那些没有改变）：


清单 8. 深入挖掘跟踪输出



清单 10 显示了清单 9 配置生成的输出的一个示例。完整的输出非常长，且 有很多重复，因此我只包括了一个示例。在这里分析 Axis XML 消息处理的细节，以及 各个方法调用所用的时间并没有多大意义 —— 它只是在处理消息的各个组件时所做 的调用的数量叠加。


清单 10. 二次深入挖掘跟踪输出




结束语

本月专栏展示了跟踪型的方面如何提供关于程序执行的有用信息。它们可以取代嵌入到程序代码 中的日志语句吗？在我看来，还不能全部取代，因为日志通常用于记录开发人员或者用户感兴趣的特定信息， 这些信息只能在方法的逻辑中访问（在这些地方不能定义切入点）。出于性能考虑，禁止日志后， 甚至可能不会生成这些信息。我在本月专栏中分析的 Axis 代码包含许多提供了这种特殊信息的日志语句。

其他类型的日志语句由简单的方法进入和退出信息组成。用一个可以在运行时激活的外部方面 可以容易地替代它们。这个方面可以设计为使用嵌入日志代码所使用的同样日志框架， 这样合在一起的输出就可以给出程序执行的综合视图。我不准备写一个这样的方面，但是希望 本专栏的这些文章可以使您更清楚如何在自己的应用程序中使用这种方法。

下个月我将分析 ASM 字节码操作框架。ASM 是我在关于 classworking 的以前的文章中讨论过的 Javassist 和 BCEL 框架的另一种选择。 它提出了一些令人印象深刻的性能要求（claim），因此我将分析性能和易用性，重写了为 Javassist 和 BCEL 所写的一些例子以在 ASM 中使用。

http://www.ibm.com/developerworks/cn/java/j-cwt04055.html