11

在 Solaris SPARC 机器上对一些 Java 代码进行基准测试时,我注意到我第一次调用基准测试函数时,它的运行速度非常慢(相差 10 倍):

  • 第一 | 1 | 25295.979 毫秒
  • 第二 | 1 | 2256.990 毫秒
  • 第三| 1 | 2250.575 毫秒

为什么是这样?我怀疑 JIT 编译器,有没有办法验证这一点?

编辑:根据一些答案,我想澄清一下,这段代码是我能找到的表现这种行为的最简单的测试用例。所以我的目标不是让它快速运行,而是要了解发生了什么,这样我就可以在我的实际基准测试中避免它。

已解决: Tom Hawtin 正确地指出我的“慢”时间实际上是合理的。根据这一观察,我将调试器附加到 Java 进程。在第一个过程中,内部循环如下所示:

0xf9037218:     cmp      %l0, 100
0xf903721c:     bge,pn   %icc,0xf90371f4        ! 0xf90371f4
0xf9037220:     nop
0xf9037224:     ld       [%l3 + 92], %l2
0xf9037228:     ld       [%l2 + 8], %l6
0xf903722c:     add      %l6, 1, %l5
0xf9037230:     st       %l5, [%l2 + 8]
0xf9037234:     inc      %l0
0xf9037238:     ld       [%l1], %g0
0xf903723c:     ba,pt    %icc,0xf9037218        ! 0xf9037218

在以下迭代中,循环如下所示:

0xf90377d4:     sub      %l2, %l0, %l3
0xf90377d8:     add      %l3, %l0, %l2
0xf90377dc:     add      %l2, 1, %l4
0xf90377e0:     inc      %l0
0xf90377e4:     cmp      %l0, 100
0xf90377e8:     bl,pn    %icc,0xf90377d8        ! 0xf90377d8

因此,HotSpot 从内部循环中移除了内存访问,将其加速了一个数量级。

教训:做数学!我应该自己做汤姆的计算。

基准 Java 代码:

    private int counter;
    private int nThreads;

    private void measure(String tag) throws Exception {
            MyThread threads[] = new MyThread[nThreads];
            int i;

            counter = 0;

            for (i = 0; i < nThreads; i++)
                    threads[i] = new MyThread();

            long start = System.nanoTime();

            for (i = 0; i < nThreads; i++)
                    threads[i].start();

            for (i = 0; i < nThreads; i++)
                    threads[i].join();

            if (tag != null)
                    System.out.format("%-20s | %-2d | %.3f ms \n", tag, nThreads,
                                     new Double((System.nanoTime() - start) / 1000000.0));
    }
    public MyBench() {
            try {
                    this.nThreads = 1;
                    measure("First");
                    measure("Second");
                    measure("Third");
            } catch (Exception e) {
                    System.out.println("Error: " + e);
            }
    }

    private class MyThread extends Thread {
            public void run() {
                    while (counter < 10000000) {
                            // work
                            for (int j = 0; j < 100; j++)
                                    counter++;
                            counter -= 99;
                    }
            }
    }
4

11 回答 11

8

一些丑陋、不切实际的代码(微基准测试的东西):

                while (counter < 10000000) {
                        // work
                        for (int j = 0; j < 100; j++)
                                counter++;
                        counter -= 99;
                }

那么这是在做什么以及它应该运行多快。

内部循环将 counter 递增 100 次,然后将 counter 递减 99。因此递增 1。注意 counter 是外部类的成员变量,因此存在一些开销。然后运行 ​​10,000,000 次。所以内部循环运行了 1,000,000,000 次。

一个使用访问器方法的循环,称为 25 个循环。在 1 GHz 时 1,000,000,000 次,为 25 秒。

嘿,我们预测了慢速时间。慢的时间很快。快速时间是在基准以某种方式被打破之后 - 2.5 个周期的迭代?使用 -server 你可能会发现它变得更加愚蠢。

于 2009-05-13T21:17:19.267 回答
5

可能是类加载或本地方法的动态链接。如果您使用以下 JVM 参数运行 Java(完整列表请参见此处),它将打印有关花费时间的信息:

-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation

要准确找出每个 measure() 调用的开始和结束位置,请在这些方法之间添加一些新类的初始化作为标记,以便-verbose:class在日志中的哪个点显示标记类被加载。有关类似测量,请参阅此答案。

为了准确了解您的代码的作用,我对其进行了如下修改:

public MyBench() {
    try {
        this.nThreads = 1;
        new Mark1();
        measure("First");
        new Mark2();
        measure("Second");
        new Mark3();
        measure("Third");
        new Mark4();
    } catch (Exception e) {
        System.out.println("Error: " + e);
    }
}

private static class Mark1 {
}
private static class Mark2 {
}
private static class Mark3 {
}
private static class Mark4 {
}

然后通过查看 JVM 何时加载那些 Mark1 等类,结果如下。

在第一次调用 measure() 期间,总共加载了 85 个类,动态链接了 11 个本地方法,并 JIT 编译了 5 个方法:

[Loaded MyBench$Mark1 from file:/D:/DEVEL/Test/classes/]
[Loaded java.net.InetSocketAddress from shared objects file]
[Loaded java.net.InetAddress from shared objects file]
[Loaded MyBench$MyThread from file:/D:/DEVEL/Test/classes/]
[Loaded sun.security.action.GetBooleanAction from shared objects file]
[Dynamic-linking native method java.net.InetAddress.init ... JNI]
[Loaded java.net.InetAddress$Cache from shared objects file]
[Loaded java.lang.Enum from shared objects file]
[Loaded java.net.InetAddress$Cache$Type from shared objects file]
[Loaded java.net.InetAddressImplFactory from shared objects file]
[Dynamic-linking native method java.net.InetAddressImplFactory.isIPv6Supported ... JNI]
 22       MyBench::access$508 (12 bytes)
[Loaded java.net.InetAddressImpl from shared objects file]
[Loaded java.net.Inet4AddressImpl from shared objects file  1%      MyBench$MyThread::run @ 14 (48 bytes)
]
[Loaded sun.net.spi.nameservice.NameService from shared objects file]
[Loaded java.net.InetAddress$1 from shared objects file]
[Loaded java.net.Inet4Address from shared objects file]
[Dynamic-linking native method java.net.Inet4Address.init ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketCreate ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketBind ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketListen ... JNI]
[Loaded java.net.Socket from shared objects file]
[Dynamic-linking native method java.net.PlainSocketImpl.socketAccept ... JNI]
[Loaded java.lang.Integer$IntegerCache from shared objects file]
[Loaded java.util.Formatter from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.regex.Pattern$6 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.text.DecimalFormatSymbols from shared objects file]
[Loaded java.util.spi.LocaleServiceProvider from shared objects file]
[Loaded java.text.spi.DecimalFormatSymbolsProvider from shared objects file]
[Loaded sun.util.LocaleServiceProviderPool from shared objects file]
[Loaded java.util.LinkedHashSet from shared objects file]
[Loaded sun.util.LocaleServiceProviderPool$1 from shared objects file]
[Loaded java.util.ServiceLoader from shared objects file]
[Loaded java.util.ServiceLoader$LazyIterator from shared objects file]
[Loaded java.util.ServiceLoader$1 from shared objects file]
[Loaded java.util.HashMap$EntrySet from shared objects file]
[Loaded java.util.LinkedHashMap$LinkedHashIterator from shared objects file]
[Loaded java.util.LinkedHashMap$EntryIterator from shared objects file]
[Loaded sun.misc.Launcher$1 from shared objects file]
 23  !    java.io.BufferedReader::readLine (304 bytes)
[Loaded sun.misc.Launcher$2 from shared objects file]
[Loaded sun.misc.URLClassPath$2 from shared objects file]
[Loaded java.lang.ClassLoader$2 from shared objects file]
[Loaded sun.misc.URLClassPath$1 from shared objects file]
[Loaded java.net.URLClassLoader$3 from shared objects file]
[Loaded sun.misc.CompoundEnumeration from shared objects file]
 24       sun.nio.cs.UTF_8$Decoder::decodeArrayLoop (553 bytes)
[Loaded java.io.FileNotFoundException from shared objects file]
[Loaded java.net.URLClassLoader$3$1 from shared objects file]
[Dynamic-linking native method java.security.AccessController.doPrivileged ... JNI]
[Loaded sun.util.resources.LocaleData from shared objects file]
[Loaded sun.util.resources.LocaleData$1 from shared objects file]
[Loaded java.util.ResourceBundle$Control from shared objects file]
[Loaded sun.util.resources.LocaleData$LocaleDataResourceBundleControl from shared objects file]
[Loaded java.util.Arrays$ArrayList from shared objects file]
[Loaded java.util.Collections$UnmodifiableCollection from shared objects file]
 25       java.lang.String::startsWith (78 bytes)
[Loaded java.util.Collections$UnmodifiableList from shared objects file]
[Loaded java.util.Collections$UnmodifiableRandomAccessList from shared objects file]
[Loaded java.util.ResourceBundle from shared objects file]
[Loaded java.util.ResourceBundle$1 from shared objects file]
[Dynamic-linking native method java.util.ResourceBundle.getClassContext ... JNI]
[Loaded java.util.ResourceBundle$RBClassLoader from shared objects file]
[Loaded java.util.ResourceBundle$RBClassLoader$1 from shared objects file]
[Loaded java.util.ResourceBundle$CacheKey from shared objects file]
[Loaded java.util.ResourceBundle$CacheKeyReference from shared objects file]
[Loaded java.util.ResourceBundle$LoaderReference from shared objects file]
[Loaded java.util.ResourceBundle$SingleFormatControl from shared objects file]
[Loaded sun.util.LocaleDataMetaInfo from shared objects file]
[Loaded java.util.AbstractList$Itr from shared objects file]
[Loaded java.util.ListResourceBundle from shared objects file]
[Loaded sun.text.resources.FormatData from shared objects file]
[Dynamic-linking native method java.lang.Class.isAssignableFrom ... JNI]
[Loaded java.util.ResourceBundle$BundleReference from shared objects file]
[Loaded sun.text.resources.FormatData_fi from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.text.resources.FormatData_fi_FI from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Currency from shared objects file]
[Loaded java.util.Currency$1 from shared objects file]
[Loaded java.util.CurrencyData from shared objects file]
[Loaded sun.reflect.UnsafeFieldAccessorFactory from shared objects file]
[Loaded sun.reflect.UnsafeQualifiedStaticFieldAccessorImpl from shared objects file]
[Loaded sun.reflect.UnsafeQualifiedStaticObjectFieldAccessorImpl from shared objects file]
[Loaded java.util.spi.CurrencyNameProvider from shared objects file]
[Loaded sun.util.resources.OpenListResourceBundle from shared objects file]
[Loaded sun.util.resources.LocaleNamesBundle from shared objects file]
[Loaded sun.util.resources.CurrencyNames from shared objects file]
[Loaded sun.util.resources.CurrencyNames_fi_FI from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.regex.MatchResult from shared objects file]
[Loaded java.util.regex.Matcher from shared objects file]
[Loaded java.util.regex.ASCII from shared objects file]
[Loaded java.util.Formatter$FormatString from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$FormatSpecifier from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$Flags from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$Conversion from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$FixedString from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formattable from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
First                | 1  | [Loaded sun.misc.FormattedFloatingDecimal from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$1 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$Form from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$2 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
2072,825 ms 

在第二次调用期间,只有一个方法被 JIT 编译:

[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
 26       MyBench$MyThread::run (48 bytes)
Second               | 1  | 2058,669 ms 

在第三次通话期间,没有发生额外的工作:

[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third                | 1  | 2093,659 ms 

这是在带有 jdk1.6.0_11 的 Windows 上运行的,因此您的系统可能会做一些不同的事情。例如,可能动态方法的链接之一在您的系统上异常缓慢。或者然后所有的类加载都比较慢。尝试查看日志,是否有异常长的暂停,或者所有这些操作是否同样缓慢。

于 2009-05-13T21:31:26.107 回答
3

添加类加载作为嫌疑人。类在第一次引用时延迟加载。所以代码第一次运行时,你可能是第一次引用一些类。

于 2009-05-13T20:35:55.837 回答
3

验证 JIT 编译器是否是后续迭代中加速的原因的最佳方法是在关闭 JIT 编译器的情况下运行基准测试。为此,请指定系统属性java.compiler=NONE(单词“none”必须大写)。

花在类加载上的时间也会导致基准代码在第一次运行时变慢。最后,调用 Thread.start() 和调用 Thread 的 run() 方法之间存在不确定的延迟。

您可能需要考虑寻找一个基准框架。一个好的框架会通过运行多次迭代来“预热”代码,然后用不同的迭代次数进行多次计时。请参阅Java 理论与实践:有缺陷的微基准分析

于 2009-05-13T21:04:27.540 回答
1

这是一个有趣的问题。我怀疑 JIT 编译器,但这些是我的数字:

第一 | 1 | 2399.233 毫秒
第二 | 1 | 2322.359 毫秒
第三| 1 | 2408.342 毫秒

可能 Solaris 正在用线程做一些有趣的事情;你试过nThreads = 10吗?

于 2009-05-13T20:34:22.127 回答
1

我建议您使 nThread = Runtime.getRuntime().availableProcessors() 这将为您提供最佳线程数以使用系统中的所有内核。

您可以尝试关闭 JIT 以查看它有什么不同。

于 2009-05-13T20:43:31.457 回答
1

您可以让 VM 记录有关类加载和编译的信息,尝试以下 VM 参数: -XX:+PrintCompilation -XX:+TraceClassLoading 这可能会提供一些关于幕后发生的事情的更多线索。

编辑:我不确定这些选项在 java 1.5 中是否有效(我在 1.6 中使用过它们)。我会尝试检查...再次编辑:它适用于java 1.5(注意您需要+,而不是-,或者您关闭该选项...)

于 2009-05-13T20:54:12.173 回答
1

我相信您也可以使用 -Xint 的 java 命令的非标准选项来禁用 HotSpot 并仅解释您的代码。这至少可以将 HotSpot 排除在解释您的时间安排之外。

于 2009-05-13T21:11:31.473 回答
0

它是工作中的热点编译器。AFAIK,第一次运行函数,运行“解释”并分析执行路径,然后JIT编译器可以优化后续的函数调用。

于 2009-05-13T20:34:59.943 回答
0

它肯定是热点编译器。如果您在 64 位 solaris 上运行,则默认为服务器 VM,热点在第一次执行时开始优化。在客户端虚拟机上,代码可能需要在热点启动之前运行几次。(我相信 solaris 只有服务器虚拟机,但我可能错了)

于 2009-05-13T20:47:03.090 回答
0

请参阅http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.html了解启动器如何在客户端和服务器 VM 之间进行选择,以及不同处理器和操作系统支持的内容。

于 2009-05-13T21:01:38.637 回答