关注性能: 什么时候好的基准测试不好了（性能测试常常产生意外结果）

 

    在进行基准测试操作时，一定要对出现意外结果有思想准备。即使您认为自己知道会是什么样的结果，可是奇怪的结果常常会让您无所适从。性能专家 Jack Shirazi 和 Kirk Pepperdine 一直在与意外结果打交道。请跟他们一起对 Java 5.0 中的一种新语言功能进行基准测试并发现一些不寻常的结果。

在 JDK 5.0 引入的所有新语言功能之中，新的 foreach 循环应当对性能没有影响。foreach 循环是一种紧凑的表示法，人们可以用它遍历集合或者数组（有关 foreach 的更多信息请参阅 参考资料）。但是这种新的语法真的像它看起来那样对性能没有影响吗？本月，我们将进行一些微性能基准测试（micro performance benchmark）以确定是否真的是这样。

构建一个 for 循环基准测试

首先，我们需要开发一个基准测试，它测量遍历集合的传统方法的性能。清单 1 显示了一个测量用标准方式遍历集合所用时间的例子：

清单 1. 基线遍历基准测试

               
private long baseline() {
    long start = System.currentTimeMillis();
    Iterator iter = this.baselineTestSet.iterator();
    while (iter.hasNext()) {
        String s = (String) iter.next();
    }
    return System.currentTimeMillis() - start;
}


像大多数基准测试一样，第一步是记录当前系统时间。然后我们声明一个 iterator 以遍历 ArrayList 中的所有元素。这个测试中使用的 ArrayList 预先装载了一百万个 String 对象，每个长度为 1，这是保证基准测试占用内存最少的一个技巧。

严格管理内存很重要，这样，垃圾收集和其他内存管理问题就不会影响基准测试结果。微性能基准测试对于占用 CPU 时间或者其他重要计算资源的任何外部因素是特别敏感的。因为内存管理占用 CPU 时间，并且因为我们感兴趣的是测量这段代码占用了多少 CPU 时间，因此系统中执行的任何其他线程如 GC，都会扭曲我们的测试结果。

控制进程占用的内存还有另一个原因：系统管理大进程更困难一些。 占用很多内存的进程通常会迫使底层操作系统将这个进程的部分地址空间交换到磁盘上。这种页面调度（paging）活动会使应用程序的执行变得断断续续， 并干扰我们的测试程序的运行时。虽然在大型基准测试中这种断续可能不会引起注意，但是微性能基准测试对此是特别敏感的。

在清单 1 的遍历循环中，可以看到从数组 list 中提取的元素被强制转换为 String。尽管对于 5.0 的基准测试我们不显式使用强制转换，但是我们需要在基线测量中加入它， 因为这是使遍历具有实用性所必需的。清单 2 使用了 foreach 语法来创建与清单 1 中所使用的方法语义相同的代码。

清单 2. 用增强的语法遍历 ArrayList

               
private long benchmark() {
    long start = System.currentTimeMillis();
    for (String s : genericTestSet) {}
    return System.currentTimeMillis() - start;
}


这个新语法要紧凑得多，并且它使循环正文减少到没有了。一个无正文的 for 循环实际上是死代码，编译器会清除任何发现的死代码。这种行为使清单 2 中的代码所报告的运行时间为 0 毫秒，这体现了编写好的基准测试时所遇到的一个经典挑战：保证编译器不优化掉让它处理的代码。

清单 3 中的代码包含了让编译器不清除 foreach 循环的技巧。 我们只要将 String 的长度加到一个实例变量中， 这保证在循环的正文中会执行一些操作。

清单 3. 防止死代码清除

               
private long baseline() {
    long start = System.currentTimeMillis();
    Iterator iter = this.baselineTestSet.iterator();
    while (iter.hasNext()) {
        String s = (String) iter.next();
        this.totalLength += s.length();
    }
    return System.currentTimeMillis() - start;
}
private long benchmark() {
    long start = System.currentTimeMillis();
    for (String s : genericTestSet) {
        this.totalLength += s.length();p
    }
    return System.currentTimeMillis() - start;
}


我们需要采取一些预防措施以保证只对要测量的时间计时。一个会影响基准测试计时的后台线程是垃圾收集（GC）。当 JVM 发现堆快满时就会触发 GC。我们不希望堆太大，但是我们应当尽量将堆设置为足够大，这样在基准测试运行时 JVM 就不会触发它。相反，我们要在选定的时间触发它。

-verbose:gc 设置用于告诉垃圾收集器在它活跃时进行记录。因为我们的目标是消除 GC，所以我们可以用这个设置检查 GC 的活动。如果看到了 GC 活动，那么我们就知道需要增加 Java 堆的大小并重新运行测试。如果在运行基准测试期间没有出现 GC，那么就可以去掉 -verbose:gc 设置。

我们在这里使用这种技术时，发现需要 Java 堆的大小为 256 MB。以后的所有运行都使用了标志 -Xmx256m。因为知道基准测试需要 256 MB 并且希望消除所有其他活动，所以我们使用 -Xms256m 设置来强制 JVM 在启动时取得它将需要的所有堆。

从计时中排除 GC 并不意味着可以忽略用于算法运行的内存管理。只是需要以可控制的方式引入它，这样我们就可以将执行简档（execution profile）与内存管理的开销区分开。

GC 还有其他需要考虑的内容。在某些时候，GC 会“stop the world”（停止所有应用程序线程）并独自运行。在其他时候，它与应用程序线程并发运行。但是因为 GC 只在我们要求的时候运行，所以不用担心它的大部分过程，只有收集过程的结束部分会与我们的应用程序线程并发运行并会影响计时。为照顾到这一点，我们在应用程序线程中，在调用 System.gc() 后加入一个短时间的 sleep。这个 sleep 的作用是让 GC 的最后阶段完成后才继续运行基准测试。

System.gc() 尽管对 System.gc() 的调用只是一个可以被 VM 忽略的建议， 但是我们从来没见过在没有明确告诉 VM 忽略这种调用的情况下，它会忽略这种 调用。

运行基准测试

 

我们在 Microsoft Windows XP Pro 上的 JDK 5.0 上运行这个基准测试。这台计算机的配置是 1.6-GHz Intel Pentium M 和 1 GB 实际内存，操作系统配置为无交换空间，并关闭了所有非必需进程。用开关 -Xmx512M 和 -Xms512M 运行 JVM。

如前所述，目标是让基线和基准测试执行相同的功能。就是说，将一百万个 String 对象从一个 ArrayList 拷贝到预设大小的目标 ArrayList。在每一种方法的结果是完全相同的（对象传送到新的 ArrayList）的情况下，我们应当可以确定两种技术的相对效率。

测试开始时运行一次基准测试，它将让 JVM 方法缓冲区“热身（warm up）”。热身了方法缓冲区后，在进行任何测量之前，让 HotSpot 进行编译和优化。热身后，我们触发一个 GC，sleep 一小会儿，并执行 100 次基线测试。这次运行的时间在表 1 中报告。基线测试后，我们立即在同样条件下运行基准测试。这些时间也可在表 1 中找到。

表 1. 执行时间统计（单位 毫秒）

	基线测试	基准测试
平均（毫秒）	160	162
方差	18	17
标准偏差	4.3	4.2
中间值（毫秒）	160	160
最大值（毫秒）	171	171
最小值（毫秒）	160	160

结果

计时显示与我们预期的完全一样：使用这两种技术的计时没有区别。因此，新的语法具有减小代码体积、同时对性能没有影响的优点。对图 1 和 2 所示的内存简档（profile）的简单观察发现了另一个未曾料到的结果：这两种技术有同样的内存使用简档（profile）。

图 1. 基线测试的 verbose GC 输出一览

图 2. 基准测试 的 verbose GC 输出一览

意外的结果

虽然结果与预想的一样，但是测试中有些地方感觉不太对头。在预测试时，我们有时会看到一个数据点的测量值为 60 毫秒。进一步的检查确定这个值不是计时器的缺陷造成的，这意味着测试中有些地方出错了。这是由什么原因造成的呢？

增加一个对 sleep() 的调用是我们在使用另一种运行在 JDK 1.4.x 下的基准测试时所发现的一种技术。JDK 5.0 GC 的一些默认行为与 JDK 1.4.x 不同，所以有可能该技术在 JDK 5.0 下不再有效。为了确认对 sleep() 的调用没有问题，我们去掉了它并重新进行测试。结果列在表 2 中。

表 2. 在 JDK 5.0 下不同配置时运行基线测试的结果

	有 GC 和 Sleep	有 GC 无 Sleep	无 Sleep 无 GC
平均（毫秒）	150	57	58
方差	1.1	23	25
标准偏差	1	4.8	5
中间值（毫秒）	150	60	60
最大值（毫秒）	160	80	91
最小值（毫秒）	150	50	50

显然，有些地方不同了。用 -verbose:gc 标志重新运行测试，确定 GC 在代码的计时部分没有运行。在 JDK 1.4.2_4 下运行测试表明这种效果不局限于 5.0。 在不同的平台和操作系统下进行测试，我们了解到在任何运行 Windows XP（并且只是 Windows XP）的机器上的基准测试中增加 sleep() 会导致显著的性能降低。 因为测试在 Windows 2000 和 Windows Server 2003 上运行都没问题，看来这不像是 Java VM 的问题。

回到 C

虽然很显然这个问题不是由 JVM 而是由操作系统造成的， 但是我们仍然需要设计一种测试来确认这个假设。为此，我们构建了一个大量占用 CPU 的 C 进程，它模拟 Java 基准测试的活动。这段代码在各次运行时，可以调用或不调用 sleep() 。这个程序所生成的结果表明，向 mix 添加了 sleep() 后，与在 Java 代码中一样， 性能也会下降。考虑到这种结果，我们将注意力从 JVM 转移到了更底层。

一个新的假设

让我们花点时间对证据进行分析以确认它是否可以证明新的假设。让一个线程 sleep：

• sleep 结束后，会使性能降低。
• CPU 在 sleep 时处于空闲状态。
• 可在 C 中重现，因而不限于 Java 语言。
• 只在 Windows XP 中运行时出现。

线程在苏醒时出现问题（让我们称它为醉线程）这一事实让我们去注意线程调度问题或者 CPU 在 sleep() 后很缓慢的情况。如果我们检查代码，就可以排除线程调度带来问题的可能性，因为计时器只能在线程运行时启动。这不能消除线程受到干扰的可能性，但是其他测试表明现这种情况只在线程苏醒后很短时间内发生。

过度的资源节省

另一种可能性是 CPU 在线程苏醒后变慢。我们可以通过在基准测试运行的同时运行一个低优先级的后台线程测试，使 CPU 不处于空闲状态来测试这一点。 在这种条件下得到的测试结果只比从基准测试结构中删除 sleep() 调用的结果差一点。这表明嫌疑犯是 Windows XP 的 CPU 时钟速度管理。

降低 CPU 时钟速度不仅节省少许资源，而且它还有助于使 CPU 运行温度更低。因此，我们猜测当 Windows XP 判断 CPU 处于空闲状态时，它就触发或者允许 CPU 降低其时钟速率。当 sleep 结束、应用程序再次开始要求 CPU 周期时，CPU 再次启动，但是看来这个过程需要相当的时间。通过运行低优先级的后台线程， 我们迫使 CPU 持续在其最大速率上运行。




结束语

尽管这个基准测试初看起来是一个证明某个应该没有任何问题的结论的无趣的过程， 可是最终我们从中了解到了基准测试对于它们的环境是多么敏感。 它还表明出错是多么容易，以及对结果进行反复检查是多么重要。 对于任何其他现象，只要可以在可控制的环境中用构造的方法重现某一观察结果， 就可以准确判断所发生的事情。

 

 

 

 

 

转自http://www.ibm.com/developerworks/cn/java/j-perf03085/