第一次运行Java循环为什么会很慢?[Sun HotSpot 1.5,sparc]

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;
                    }
            }
    }

我想不到一种简单的方法来验证它是 JIT 编译器,但我可以说几乎肯定是 Hotspot 开始将循环编译成本地代码。 - Kekoa
1
顺便说一下,如果您有多个线程,这个基准测试将会更加不可靠。因为您正在使用全局变量来控制外部循环,每个线程很可能循环的次数不同;可能多于10000000次,也可能少于。 - Michael Myers
1
顺便问一下(再次),这可能是一个愚蠢的问题,但你是否运行过类似结果的多次测试?单个测试基本上没有意义。 - Michael Myers
根据我的计算,在1 GHz处理器上,即使是“快速”时间每个增量也需要200个周期,这对我来说似乎太慢了(我不会惊讶地看到-server将所有优化都消除)。 - Tom Hawtin - tackline
啊。我的错误,我读错了代码... - Tom Hawtin - tackline
11个回答

8

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

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

那么这段代码是做什么的?它应该跑多快呢?

内部循环将计数器增加100次,然后将计数器减少99次,相当于每次增加1。请注意,计数器是外部类的成员变量,因此有一些额外开销。这个过程将运行10,000,000次。所以内部循环总共运行了1,000,000,000次。

使用两个访问器方法的循环,称为25个周期。在1 GHz下运行1,000,000,000次,需要25秒。

嘿,我们预测的时间其实很快。只有在某种方式破解基准测试后才会出现更快的结果 - 每次迭代2.5个周期?使用-server选项,您可能会发现它变得更加荒谬。


访问方法可以内联,消除开销。循环可以展开,减少开销,并且现代处理器具有分支预测功能,可以同时执行多个操作,因此每次迭代平均2.5个周期是正常的。 - ggf31416
循环和循环可以被删除 - 比内联虚拟方法更容易。因此,每次迭代平均0.0个周期是正常的。 - Tom Hawtin - tackline
Tom,谢谢。根据你的提示,我还在C中对这段代码进行了基准测试(验证汇编代码),结果也需要大约20秒。所以我附加了一个调试器到Java进程上。结果发现,在第一次measure()调用之后,JIT编译器优化了内部循环中的内存访问,并使循环在寄存器上工作。 - Adam Morrison
如果JIT最终将该代码优化为“count = 10000000;”,我甚至不会感到惊讶。 - Esko Luontola
是的,这是服务器 HotSpot 可能会做的事情。如果将计数器分配为零,则可能会执行此操作。目前它必须执行类似于 if (this$0.count < 10000000) this$0.count = 10000000; 的操作。不是最好的基准测试。 - Tom Hawtin - tackline

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个本地方法,编译了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 

这是在Windows上使用jdk1.6.0_11运行的,因此您的系统可能会有一些不同的操作。例如,也许其中一种动态方法链接在您的系统上特别慢。或者所有类加载都变慢了。请查看日志,看是否存在异常长时间的暂停,或者所有这些操作都同样缓慢。


没错,如果系统没有出现严重故障,那么这样的情况确实很不寻常。汤姆和亚当找到了真正的原因。 - Esko Luontola

3

将类加载添加为可疑项。类在首次引用时懒加载。因此,当代码第一次运行时,您可能是第一次引用某些类。


3
验证JIT编译器是否是后续迭代加速的原因的最佳方法是在关闭JIT编译器的情况下运行基准测试。为此,请指定系统属性java.compiler=NONE(单词“none”必须大写)。
执行类加载所花费的时间也会导致第一次运行基准测试代码变慢。最后,调用Thread.start()和Thread的run()方法被调用之间存在不确定的延迟。
您可能需要考虑找到一个基准测试框架。一个好的框架将通过运行多个迭代来“预热”代码,然后使用不同数量的迭代进行多次计时。请参见Java理论与实践:有缺陷的微基准分析

1

这是一个有趣的问题。我猜测是JIT编译器,但以下是我的数字:

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

可能是Solaris在处理线程方面出了些问题;您尝试过使用 nThreads = 10 或类似的值吗?


这是一份简化后的代码版本,尽管它表现出相同的行为。我只是想在这里发布最简单的情况。换句话说,我并不试图让这个特定的基准测试尽可能快,而是想要理解这里出了什么问题,以免影响我真正的基准测试。 - Adam Morrison

1

我建议你将 nThread = Runtime.getRuntime().availableProcessors(),这样可以得到最佳线程数,以利用系统中的所有核心。

你可以尝试关闭JIT,看看有什么不同。


谢谢,我不是在尝试让这段特定的代码变快,而是在努力理解它背后发生了什么,以使其表现出这种行为。 - Adam Morrison
当Java第一次运行代码时,它以解释模式运行。这是因为大多数代码只执行一次,不值得在这种情况下编写代码。当代码重复使用时,它会被优化,并且可以根据代码使用方式的变化进一步优化。默认情况下,完全优化要等到某些东西被调用10,000次才会进行。这样做是为了在优化代码之前收集有关代码使用情况的统计信息。例如,减少此数字可能会导致长期性能较差。 - Peter Lawrey

1
你可以让虚拟机记录有关类加载和编译的信息,尝试以下虚拟机参数: -XX:+PrintCompilation -XX:+TraceClassLoading 这可能会提供一些关于内部发生情况的进一步线索。
编辑:我不确定这些选项是否适用于Java 1.5(我在1.6中使用过它们)。我会尝试检查一下... 再次编辑:它适用于Java 1.5(请注意,您需要使用+而不是-,否则您将关闭该选项...)

1

我相信你也可以使用java命令的非标准选项-Xint来禁用HotSpot,并只解释你的代码。这至少可以将HotSpot从解释你的时间中排除。


0

这是热点编译器在工作。据我所知,第一次运行函数时,会以“解释”的方式运行,并分析执行路径,然后JIT编译器可以优化后续的函数调用。


1
它应该在中途替换堆栈上的代码(该代码于2000年引入)。也许这个示例中有什么阻止它的东西。 - Tom Hawtin - tackline

0

这肯定是热点编译器的问题。如果你在64位Solaris上运行,默认使用服务器VM,热点编译器会在第一次执行时开始优化。在客户端VM上,代码可能需要运行几次才能启动热点编译器。(我相信Solaris只有服务器VM,但我可能错了)


网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接