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

在这一期的 Classworking 工具箱 中，顾问 Dennis Sosnoski 接着上个月，使用面向方面的（aspect-oriented）方法进行性能分析。他用 Apache Axis Web 服务框架分析了一个客户机应用程序，以找出执行时间都花在哪里了。同时，Dennis 分析了 Java 代码中的测量时间间隔问题，并展示了如何找出自己系统上计时器实现的粒度和开销。

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

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

适时的离题

我的性能跟踪方面的主要目的是监视程序的执行，并给出执行时间从上到下的视图（与通常用 profiler 得到的从下到上的视图正好相反）。要真正有效地使用它，需要对时间是如何测量的多少有一些了解。

Java 编程语言有一个计时方法，从早期版本起它就是标准 API 的一部分。这个方法是 java.lang.System.currentTimeMillis()，它返回从 UTC 1970 年 1 月 1 日午夜开始经过的毫秒数。这个方法非常有用，特别是它在各个版本的 Java 平台上都有。因此，在上个月我的初始方面演示代码中，我使用了它。不过，currentTimeMillis() 也有一些缺点。

currentTimeMillis() 的一个问题是，它虽然是以毫秒计数返回时间，但是不能保证返回的计数的粒度或精度。在一些系统上，时间是真正的毫秒计数，大约每一毫秒改变一次。在另一些系统上，时间可能每隔 10 或 20 毫秒才变一次，因此每一次的精度都可能变化。

另一个局限是在方法定义中的基本时间单位。当 Java 平台第一次开始使用时，一毫秒仍然是相当短的时间间隔（特别是对于解释语言）。今天，随着 CPU 时钟速度比第一次发布 Java 平台时快了近一百倍，一毫秒已经成了相对长的一段时间。

除了 currentTimeMillis() 的这些问题，还有另一个使用任何类型的计时器方法监视程序执行都会有的问题。这个问题是计时器方法本身 —— 可能要深入操作系统才能访问计时器 —— 这增加了一些开销，如果计时器方法开销过大（或者方法调用过于频繁），那么就会严重扭曲计时测量。为了明智地使用我们的性能跟踪方面，我需要至少大体知道计时器方法调用增加了多少开销。

计时 currentTimeMillis()

使用 currentTimeMillis() 到底有多大问题？为了澄清这一点，我编写了一个程序进行一些测试。这个程序如清单 1 所示，通过重复调用这个方法直到返回值改变，以一种非常简单的方式检查 currentTimeMillis() 的粒度、精度和开销。改变的幅度告诉我计时器的粒度，两次改变之间的调用次数可以得出每次调用的开销，而改变幅度的一致性和改变之间的调用次数让我可以检查精度。

清单 1. currentTimeMillis() 粒度

				
public class MilliGran
{
    // round value to a single digit after decimal point
    private static String roundOneDecimal(double value) {
        int whole = (int)value;
        return whole + "." + (int)((value-whole)*10.0);
    }
    
    // print average and deviation with lead text
    private static void print(String lead, double sum,
        double ssqr, int reps) {
        double mean = sum / reps;
        double stddev = Math.sqrt(ssqr/reps-mean*mean);
        System.out.println(lead + roundOneDecimal(mean) +
            ", with standard deviation " + roundOneDecimal(stddev));
    }
    
    public static void main(String[] argv) {
        
        // get control values from command line
        int reps = Integer.parseInt(argv[0]);
        int sets = Integer.parseInt(argv[1]);
        
        // loop until time rolls over
        long start = System.currentTimeMillis();
        long last;
        while ((last = System.currentTimeMillis()) == start);
        
        // loop for count of sets specified
        int[] diffs = new int[reps];
        for (int i = 0; i < sets; i++) {
            double lsum = 0.0;
            double lsumsq = 0.0;
            double dsum = 0.0;
            double dsumsq = 0.0;
            for (int j = 0; j < reps; j++) {
                
                // count loops until result changes
                int loop = 0;
                last = System.currentTimeMillis();
                long now;
                do {
                    loop++;
                    now = System.currentTimeMillis();
                } while (now == last);
                
                // accumulate statistics information
                lsum += loop;
                lsumsq += loop*loop;
                int diff = (int)(now-last);
                dsum += diff;
                dsumsq += diff*diff;
                diffs[j] = diff;
            }
            
            // print results for set
            System.out.println("Set " + i + " results:");
            print(" Average time change ", dsum, dsumsq, reps);
            print(" Average calls before change ", lsum, lsumsq, reps);
            System.out.println(" Average time per call " +
                roundOneDecimal(dsum / lsum * 1000000.0) + " nanoseconds");
            System.out.print(" Differences:");
            for (int j = 0; j < reps; j++) {
                System.out.print(" " + diffs[j]);
            }
            System.out.println();
        }
    }
}

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

清单 2. 运行 currentTimeMillis() 测试的结果

				
[dennis@notebook time]$ java -cp . MilliGran 10 4
Set 0 results:
 Average time change 1.0, with standard deviation 0.0
 Average calls before change 332.8, with standard deviation 39.4
 Average time per call 3004.8 nanoseconds
 Differences: 1 1 1 1 1 1 1 1 1 1
Set 1 results:
 Average time change 1.0, with standard deviation 0.0
 Average calls before change 338.6, with standard deviation 38.7
 Average time per call 2953.3 nanoseconds
 Differences: 1 1 1 1 1 1 1 1 1 1
Set 2 results:
 Average time change 1.0, with standard deviation 0.0
 Average calls before change 333.6, with standard deviation 33.5
 Average time per call 2996.7 nanoseconds
 Differences: 1 1 1 1 1 1 1 1 1 1
Set 3 results:
 Average time change 1.0, with standard deviation 0.0
 Average calls before change 336.8, with standard deviation 41.4
 Average time per call 2969.1 nanoseconds
 Differences: 1 1 1 1 1 1 1 1 1 1

用 nanoTime() 放大

在 JDK 5.0 中，Sun 增加了另一个方法 java.lang.System.nanoTime()，它可以提供更好的计时信息。顾名思义，nanoTime() 返回一个以纳秒为单位的时间值，提供了比 currentTimeMillis() 方法精确一百万倍的精度。即使当今的大多数系统无法提供纳秒精度的时间，但是实际值应当至少比用老的方法获得的要好得多。

很容易修改清单 1 代码以用 nanoTime() 方法代替 currentTimeMillis()。我在这里就不显示修改后的代码了（不过它包括在参考资料部分中的代码下载中），但是清单 3 显示了运行修改后的程序的结果，这一次使用了 JDK 5.0：

清单 3. 运行 nanoTime() 测试的结果

				
[dennis@notebook time]$ java -cp . NanoGran 10 4
Set 0 results:
 Average time change 2800.0, with standard deviation 400.0
 Average calls before change 1.0, with standard deviation 0.0
 Average time per call 2800.0 nanoseconds
 Differences: 3000 3000 3000 3000 2000 2000 3000 3000 3000 3000
Set 1 results:
 Average time change 2900.0, with standard deviation 300.0
 Average calls before change 1.0, with standard deviation 0.0
 Average time per call 2900.0 nanoseconds
 Differences: 3000 3000 3000 3000 3000 3000 2000 3000 3000 3000
Set 2 results:
 Average time change 2700.0, with standard deviation 458.2
 Average calls before change 1.0, with standard deviation 0.0
 Average time per call 2700.0 nanoseconds
 Differences: 2000 3000 3000 2000 3000 3000 3000 3000 3000 2000
Set 3 results:
 Average time change 2900.0, with standard deviation 300.0
 Average calls before change 1.0, with standard deviation 0.0
 Average time per call 2900.0 nanoseconds
 Differences: 3000 3000 3000 3000 2000 3000 3000 3000 3000 3000

从清单 3 的结果中可以看出，nanoTime() 方法运行得比 currentTimeMillis() 要稍快一些。但是更重要的是，每次调用后，它返回不同的时间值，看起来粒度为 1000 纳秒（或者 1 毫秒）。我是怎样知道粒度的？当然从这些结果中不能十分确定，但是对 nanoTime() 的前后两次调用的结果值之差总是 2 或者 3 毫秒这一实事则很能说明问题。

回页首

缓冲方面

将上个月的性能跟踪方面改为使用 nanoTime() 很容易。在改的时候，我还做了一些其他改变以改进代码的易用性，并让测试更灵活。清单 4 给出了相应部分做了修改的代码：

清单 4. 性能跟踪方面代码

				
public class TraceAspect
{
    private static final long DEFAULT_MINIMUM = 1000000;
    
    private final long m_minimumNanoseconds;
    private final int m_maximumNesting;
    private final String m_triggerClass;
    private final String m_triggerName;
    private int m_matchDepth;
    private int m_nestingDepth;
    private ArrayList m_pendingPrints = new ArrayList();
    
    public TraceAspect(AspectContext context) {
        
        // set minimum time value for tracing a method
        String value = context.getParameter("minimum-time");
        m_minimumNanoseconds = (value == null) ?
            DEFAULT_MINIMUM : Long.parseLong(value);
        
        // set maximum depth to be printed
        value = context.getParameter("maximum-depth");
        m_maximumNesting = (value == null) ?
            Integer.MAX_VALUE : Integer.parseInt(value);
        
        // set trigger class and method name if supplied
        value = context.getParameter("trigger-method");
        if (value == null) {
            m_matchDepth = 1;
            m_triggerClass = null;
            m_triggerName = null;
        } else {
            int split = value.lastIndexOf('.');
            m_triggerClass = value.substring(0, split);
            m_triggerName = value.substring(split+1);
        }
    }
    
    private void indent(int depth) {
        for (int i = 0; i < depth; i++) {
            System.out.print((i % 2 == 0) ? ' ' : '-');
        }
    }
    
    private void indent() {
        indent(m_nestingDepth);
    }
    
    private void printFullMethod(JoinPoint call) {
        MethodSignature signature = (MethodSignature)call.getSignature();
        System.out.print(signature.getDeclaringType().getName());
        System.out.print('.');
        System.out.print(signature.getName());
    }
    public Object trace(JoinPoint join) throws Throwable {
        
        // check for match on trigger
        boolean match = false;
        MethodSignature signature = (MethodSignature)join.getSignature();
        if (signature.getName().equals(m_triggerName)) {
            if (signature.getDeclaringType().getName().equals(m_triggerClass)) {
                match = true;
                m_matchDepth++;
            }
        }
        
        // check if execution is to be processed
        if (m_matchDepth == 0 || m_nestingDepth > m_maximumNesting) {
            
            // skip any timing or printing
            return join.proceed();
            
        } else {
            
            // add joinpoint to list pending print
            m_pendingPrints.add(join);
            m_nestingDepth++;
            
            // time joinpoint execution
            long start = System.nanoTime();
            Object result = null;
            Throwable thrown = null;
            try {
                result = join.proceed();
            } catch (Throwable t) {
                thrown = t;
            } finally {
                
                // adjust depths
                m_nestingDepth--;
                if (match) {
                    m_matchDepth--;
                }
                
                // 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.nanoTime() - start;
                if (time >= m_minimumNanoseconds || thrown != null) {
                    
                    // 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('>');
                        printFullMethod(prior);
                        System.out.println();
                    }
                    
                    // clear all pendings now that they're printed
                    m_pendingPrints.clear();
                    
                    // print exiting information including time
                    indent();
                    System.out.print(entered ? '<' : '*');
                    printFullMethod(join);
                    System.out.print(" took ");
                    long tenthmillis = (time+50000)/100000;
                    System.out.print(tenthmillis / 10);
                    System.out.print('.');
                    System.out.print(tenthmillis % 10);
                    System.out.print(" ms.");
                    
                    // append exception information
                    if (thrown != null) {
                        System.out.println(" threw " +
                            thrown.getClass().getName() +
                            ": " + thrown.getMessage());
                        throw thrown;
                    } else {
                        System.out.println();
                    }
                }
            }
            return result;
        }
    }
}

基本原理仍然与上个月一样，但是这段代码添加了几个警告。除了使用 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，那么您可能也会遇到同样的问题。

回页首

分析 Axis

准备好了清单 4 中新的和改进过的性能跟踪方面，就需要找一个目标应用程序用这个方面显微镜进行检查。我选择了 Apache Axis Web 服务框架，运行一个客户机应用程序以避免让服务器代码复杂化。因为我的主要工作是 Web 服务，因此 Axis 很适合。我曾经至少花了几周时间分析过 Axis 代码，因此我对它的结构相当熟悉 —— 不过我也还记得第一次试图跟踪这些代码采用的通常很费解的路径时有多么痛苦。

为照顾不与 Web 服务打交道的读者，下面是它的简单介绍。 Axis 是 Java Web 服务的 JAX-RPC 标准的实现。它支持客户机应用程序（它以 XML 消息的格式发出请求）和服务器端应用程序（它对收到的请求生成 XML 响应消息），大多数 Axis 代码是两端都使用的。由于 Web 消息的特性，框架的工作过程在高层上是很清楚的。在客户机端，可以归纳如下：接受来自用户代码的请求的数据、发送请求并等待响应、从响应中提取数据、最后将数据提交给用户代码。但是在 Axis 框架中这个过程的实际发生细节却很容易让人迷惑。

我已经有一个在前面的 Web 服务性能测试中使用的 Axis 客户机应用程序（请参阅参考资料中的链接），因此在本月的文章中，我将对这个客户机应用程序使用性能跟踪方面。我还要运行对应的 Axis 服务器应用程序，这样客户机就可以有响应，但是不会包括在性能跟踪中。这个应用程序的实际目的是从服务器上提取地震数据库中的信息。

高层视图

初步观察 Axis 执行时，我想看看基本时间分布，这可让我了解代码的哪些部分执行的时间最长（当然还有到达这些部分的路径）。要完成这个任务，我使用的方面配置将告诉它截获我的应用程序代码和 Axis 代码中的所有方法调用，但是最大嵌套深度只到七 —— 这样我就不会被大量细节所淹没。清单 5 给出了我将使用的 AspectWerkz 配置：

清单 5. 初步观察的配置

				

  
    
      
        
          execution(* org.apache.axis..*(..)) || execution(* com.sosnoski.seismic..*(..))

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

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

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

				
Running query for date range from 2002-04-02 13:12:53 to 2002-12-15 04:08:40,
  longitude range from 40.71031 to 160.91571,
  latitude range from -70.6799 to 22.293274,
 ->com.sosnoski.seismic.axislit.AxisDocLitClient.runQuery
 - >com.sosnoski.seismic.axislit.SeismicBindingStub.matchQuakes
 - ->org.apache.axis.client.Call.invoke
 - - >org.apache.axis.client.Call.invoke
 - - ->org.apache.axis.client.Call.invoke
 - - - *org.apache.axis.client.Call.invoke took 591.4 ms.
 - - - *org.apache.axis.message.RPCElement.getParams took 1447.0 ms.
 - - - - -  - - - ->org.apache.axis.client.Stub.extractAttachments
 - - >org.apache.axis.Message.getAttachments
 - - ->org.apache.axis.attachments.AttachmentsImpl.getAttachmentCount
 - - - *org.apache.axis.SOAPPart.saveChanges took 155.7 ms.
 - - - - -  - - -  -Results from query:
Seismic region New Zealand Region has 1 regions and 2 matching quakes
Seismic region Bismarck and Solomon Islands has 4 regions and 30 matching quakes
Seismic region New Guinea has 9 regions and 55 matching quakes
Seismic region Caroline Islands Area has 2 regions and 8 matching quakes
Seismic region Guan to Japan has 2 regions and 10 matching quakes
Seismic region Taiwan Area has 1 regions and 2 matching quakes
Seismic region Philippine Islands has 5 regions and 22 matching quakes
Seismic region Bornea - Sulawesi has 10 regions and 37 matching quakes
Seismic region Sunda Arc has 12 regions and 49 matching quakes
Seismic region Myanmar and Southeast Asia has 1 regions and 2 matching quakes
Seismic region India - Xizand - Sichuan - Yunnan has 1 regions and 2 matching quakes
Seismic region Indian Ocean has 9 regions and 27 matching quakes
Seismic region Africa has 3 regions and 3 matching quakes
Seismic region Macquarie Loop has 1 regions and 2 matching quakes
Seismic region Andaman Islands to Sumatera has 4 regions and 14 matching quakes
 -*com.sosnoski.seismic.axislit.AxisDocLitClient.summarize took 1.7 ms.
Result match count 265 in 2203 ms.

我的客户机测试程序将结果打印到控制台，这样，它们就与清单 6 中的性能跟踪信息混在一起。忽略客户机程序输出后，跟踪信息明白地告诉我时间花在什么地方了 —— 总时间的 90% 多花在 org.apache.axis.client.Call.invoke() 方法上。这个时间的不到 30% 花在用同一个名字调用另一个方法上（或者对同一方法的递归调用 —— 我从跟踪中无法区别），而所有剩下的时间实质上都花在了对 org.apache.axis.message.RPCElement.getParams() 方法的调用上。

为开销买单

通过比较清单 6 的最后一行中显示的请求的总执行时间（2203 毫秒）与不通过 AspectWerkz 运行的请求的计时，我可以大致了解到我的监视对程序增加了多少开销。在本例中，大约是 1 倍 —— 我直接运行这个程序的时间一般是在 1000 到 1100 毫秒这个范围。

为什么这个程序使用了方面后，它的运行速度只有一半了呢？有两个不同的因素增加了开销。第一个是由 AspectWerk 的字节码操作增加的，这使它可以在每当目标方法被调用时调用我的方面。第二个是由计时代码和向控制台输出跟踪所增加的。

注释掉除了 trace() 方法体中 return join.proceed(); 以外的所有内容，以便惟一的开销就是截获方法调用所增加的，这样可以比较这两个组件。结果它只比清单 6 所显示的全部输出快约 10%，因此我知道在这里几乎所有开销都是由于调用我的方面所产生的。

如果更好地选择切入点方法 —— 比如取消对只返回一个字段值的简单 get 方法的截获，本来是可以减少这些开销的。这些简单的 get 方法可能构成了大量的方法调用，因此消除它们有可能极大地降低开销。不幸的是，对于 Axis 代码，不能根据方法名统一地做到这一点，因为它遵守标准 Java 语言的对简单和复杂的操作都使用 get 格式的名字的习惯做法。 AspectWerkz 在使用方面时，可以容易地区分简单的方法与至少进行一些处理的方法，但是没有办法告诉它从切入点中排除这些方法。因此，我保留截获开销，除非我想要减少切入点中类的数量，或者列出要从切入点中排除的各个方法。这两种方法都没有吸引力，因此我就留着这些开销，并观察在我的方法垮掉之前能得到多少有用的信息。

深入挖掘

请参阅前面的清单 6，总时间的 90% 以上都花在了 org.apache.axis.client.Call.invoke() 方法上。它自然成了更详细的性能跟踪的目标。我将使用清单 7 配置获得更详细的视图：

清单 7. 深入挖掘配置

				

  
    
      
        
          execution(* org.apache.axis..*(..)) || execution(* com.sosnoski.seismic..*(..))

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

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

				
>org.apache.axis.client.Call.invoke
 >org.apache.axis.client.Call.invoke
 ->org.apache.axis.client.Call.invoke
 - >org.apache.axis.client.Call.invoke
 - ->org.apache.axis.MessageContext.setTargetService
 - - *org.apache.axis.AxisEngine.getService took 14.9 ms.
 - - - ->org.apache.axis.client.Transport.setupMessageContext
 - - *org.apache.axis.transport.http.HTTPTransport.setupMessageContextImpl took 2.8 ms.
 - - - ->org.apache.axis.message.MessageElement.output
 - - *org.apache.axis.message.SOAPEnvelope.outputImpl took 5.8 ms.
 - - - ->org.apache.axis.client.Call.invokeEngine
 - - *org.apache.axis.client.AxisClient.invoke took 572.3 ms.
 - - - >org.apache.axis.client.Call.invoke took 602.6 ms.
 - >org.apache.axis.message.RPCElement.getParams
 - ->org.apache.axis.message.RPCElement.deserialize
 - - *org.apache.axis.message.MessageElement.publishToHandler took 1447.2 ms.
 - - -  -

这个更详细的执行时间视图开始展示一些有用的细节了。我现在可以看到对 org.apache.axis.client.Call.invoke() 最内部的调用是包装了请求处理的调用，包括对服务器的调用。这个调用在返回之前必须等待服务器响应，因此显然有大量处理是在跟踪所覆盖的范围之外进行的 —— 所有服务器代码都是在没有 AspectWerkz 的、单独的 JVM 中运行的。真正的客户机处理负荷出现在 org.apache.axis.message.RPCElement.getParams() 调用中，我可以看到实质上所有处理时间都花在对 org.apache.axis.message.MessageElement.publishToHandler() 的调用上。

超越极限

我要进一步深入挖掘，进入 org.apache.axis.message.MessageElement.publishToHandler() 方法，清单 8 输出指出它是大部分客户机处理发生的地方。清单 9 显示了完成这个任务的一个配置。在这里，我从切入点中去掉了客户机代码，因为对它不再感兴趣了，我还将加入跟踪的方法调用的最小时间减小到 .4 毫秒（以纳秒表示）。最后，我改变了用来激活对感兴趣的新方法的跟踪的触发器方法。

清单 9. 二次深入挖掘配置

				

  
    
      
                  expression="execution(* org.apache.axis..*(..))"/>

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

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

				
>org.apache.axis.message.MessageElement.publishToHandler
 >org.apache.axis.message.SAX2EventRecorder.replay
 ->org.apache.axis.encoding.DeserializationContext.startElement
 - *org.apache.axis.message.RPCHandler.onStartChild took 0.7 ms.
 - >org.apache.axis.encoding.ser.BeanDeserializer.startElement
 - ->org.apache.axis.encoding.DeserializerImpl.startElement
 - - *org.apache.axis.encoding.ser.BeanDeserializer.onStartElement took 12.8 ms.
 - - -  - ->org.apache.axis.encoding.DeserializationContext.startElement
 - *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.6 ms.
 - -*org.apache.axis.encoding.DeserializationContext.startElement took 0.6 ms.
 -*org.apache.axis.encoding.DeserializationContext.endElement took 0.5 ms.
 ->org.apache.axis.encoding.DeserializationContext.startElement
 - *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.5 ms.
 - ->org.apache.axis.encoding.DeserializationContext.startElement
 - >org.apache.axis.encoding.ser.BeanDeserializer.onStartChild
 - -*org.apache.axis.encoding.DeserializationContext.getTypeFromAttributes took 1.3 ms.
 -  - -*org.apache.axis.encoding.DeserializationContext.endElement took 0.6 ms.
 ->org.apache.axis.encoding.DeserializationContext.startElement
 - *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.4 ms.
 - ->org.apache.axis.encoding.DeserializationContext.startElement
 - >org.apache.axis.encoding.ser.BeanDeserializer.startElement
 - ->org.apache.axis.encoding.DeserializerImpl.startElement
 - - *org.apache.axis.encoding.ser.BeanDeserializer.onStartElement took 121.8 ms.
 - - -  - ->org.apache.axis.encoding.DeserializationContext.endElement
 - *org.apache.axis.encoding.DeserializerImpl.endElement took 0.5 ms.
 - ...

清单 10 展示了这个性能跟踪方面的作用的局限性。它可以很快地让您了解应用程序中最花费时间的部分，这很不错，但是在实际找出哪些代码运行得慢并且加以改进这方面不是很有用。不过，后一个问题用常规的执行 profiler 可以很好地解决，因此不会错过什么。性能跟踪和执行 profiler 可以成为分析和改进应用程序性能的有用工具。

回页首

结束语

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

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

[转载]Classworking 工具箱: 用方面跟踪性能

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