第一次Java循环运行缓慢，为什么?(太阳1.5热点,sparc)

In benchmarking some Java code on a Solaris SPARC box, I noticed that the first time I call the benchmarked function it runs EXTREMELY slowly (10x difference):

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

• First | 1 | 25295.979 ms
• 第一个| 1 | 25295.979 ms
• Second | 1 | 2256.990 ms
• 第二个| 1 | 2256.990 ms
• Third | 1 | 2250.575 ms
• 第三个| 1 | 2250.575 ms

Why is this? I suspect the JIT compiler, is there any way to verify this?

这是为什么呢?我怀疑JIT编译器，有办法验证这个吗?

Edit: In light of some answers I wanted to clarify that this code is the simplest possible test-case I could find exhibiting this behavior. So my goal isn't to get it to run fast, but to understand what's going on so I can avoid it in my real benchmarks.

编辑:根据一些答案，我想澄清这段代码是我能找到的最简单的测试用例。我的目标不是让它运行得快，而是理解发生了什么，这样我就可以在真正的基准测试中避免它。

Solved: Tom Hawtin correctly pointed out that my "SLOW" time was actually reasonable. Following this observation, I attached a debugger to the Java process. During the first, the inner loop looks like this:

汤姆·霍廷正确地指出我的“慢”时间实际上是合理的。在此观察之后，我将调试器附加到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

On the following iterations, the loop looks like this:

在以下迭代中，循环如下:

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

So HotSpot removed memory accesses from the inner loop, speeding it up by an order of magnitude.

所以HotSpot从内部循环中删除了内存访问，以一个数量级的速度提升。

Lesson: Do the math! I should have done Tom's calculation myself.

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

Benchmark Java code:

基准测试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;
                    }
            }
    }

11 个解决方案

#1

Some ugly, unrealistic code (the stuff of microbenchmarks):

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

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

So what is this doing and how fast should it run.

那么它在做什么，它应该跑多快。

The inner loop increments counter 100 times, then the counter is decremented by 99. So an increment of 1. Note counter is a member variable of an outer class, so some overhead there. This is then run 10,000,000 times. So the inner loop is run 1,000,000,000 times.

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

A loop using to accessor methods, call it 25 cycles. 1,000,000,000 times at 1 GHz, gives 25s.

用于访问方法的循环，称为25个循环。1000,000,000乘以1ghz，得到25s。

Hey, we predicted the SLOW time. The slow time is fast. The fast times are after the benchmark has been broken in some way - 2.5 cycles an iteration? Use -server and you might find it gets even more silly.

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

#2

Probably it's class loading or dynamic linking of native methods. If you run Java with the following JVM parameters (see here for full list), it will print information about what is taking the time:

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

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

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

To find out exactly where each of the measure() calls start and end, add initializations of some new classes between those methods as markers, so that -verbose:class will show at what point in the logs the marker class is loaded. See this answer for a similar measurement.

要找到每个度量()调用开始和结束的确切位置，在这些方法之间添加一些新类的初始化作为标记，以便-verbose:类将显示标记类装入的日志中的哪个点。类似的测量方法请参见此答案。

To find out exactly what your code does, I modified it like this:

为了弄清楚你的代码到底是做什么的，我这样修改了它:

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

Then by looking at when the JVM loaded those Mark1 etc. classes, here are the results.

然后通过查看JVM加载这些Mark1等类的时间，这里是结果。

During the first call to measure(), a total of 85 classes were loaded, 11 native methods were dynamically linked and 5 methods were JIT compiled:

在第一次调用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 

During the second call, only one method was JIT compiled:

在第二次调用中，JIT编译了一个方法:

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

During the third call, there was no additional work happening:

在第三次通话中，没有额外的工作发生:

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

This was run on Windows with jdk1.6.0_11, so your system might do things a little bit differently. For example, maybe one of those linkings of dynamic methods is exceptionally slow on your system. Or then all of the class loading is slower. Try to have a look at the logs, whether there is an unusually long pause, or whether all of those operations are equally slow.

这是使用jdk1.6.0_11在Windows上运行的，所以您的系统可能会有一点不同。例如，动态方法的链接在您的系统上可能会特别慢。或者所有的类加载都比较慢。尝试查看日志，是否有异常长的暂停，或者所有这些操作都是同样缓慢的。

#3

Add class loading in as a suspect. Classes are loaded lazily on first reference. So the first time the code runs, you're probably referencing some classes for the first time.

添加类装入作为怀疑。类在第一次引用时被延迟加载。所以当代码第一次运行时，你可能第一次引用了一些类。

#4

The best way to verify if the JIT compiler is the reason for the speedup in later iterations is to run the benchmark with the JIT compiler turned off. To do this, specify the system property java.compiler=NONE (the word "none" must be in upper case).

要验证JIT编译器是否是加速的原因，最好的方法是在关闭JIT编译器的情况下运行基准测试。

Time spent doing class loading can also cause the benchmarked code to run slower the first time. Finally, there is a nondeterministic delay between calling Thread.start() and the Thread's run() method being called.

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

You might want to consider finding a benchmark framework. A good framework will "warm up" the code by running several iterations, then do multiple timings with a different number of iterations. See Java theory and practice: Anatomy of a flawed microbenchmark.

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

#5

That's an interesting question. I'd suspect the JIT compiler, but these are my numbers:

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

First                | 1  | 2399.233 ms 
Second               | 1  | 2322.359 ms 
Third                | 1  | 2408.342 ms 

Possibly Solaris is doing something funny with threads; have you tried with nThreads = 10 or so?

也许Solaris在线程上做了一些有趣的事情;你试过nThreads = 10吗?

#6

I suggest you make nThread = Runtime.getRuntime().availableProcessors() This will give you the optimal number of threads to use all the cores in your system.

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

You can try turning off the JIT to see what difference it makes.

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

#7

You can get the VM to log information about classloading and compilation, try the following VM args: -XX:+PrintCompilation -XX:+TraceClassLoading This might give some further clues as to what's happening under the hood.

您可以让VM记录关于类加载和编译的信息，可以尝试以下VM args: -XX:+ printcompile -XX:+TraceClassLoading这可以提供关于在hood下面发生的事情的进一步线索。

EDIT: I'm not sure those options work in java 1.5 (I've used them in 1.6). I'll try to check... EDIT again: It works in java 1.5 (note you need +, not -, or you turn the option off...)

编辑:我不确定这些选项是否适用于java 1.5(我在1.6中使用过)。我将试着检查……再次编辑:它在java 1.5中工作(注意您需要+，而不是-，或者您关闭选项…)

#8

I believe you can also use the non-standard option for the java command of -Xint to disable HotSpot and have your code interpreted only. This could at least take HotSpot out of the equation for interpreting your timing.

我相信您还可以使用-Xint的java命令的非标准选项来禁用HotSpot，并只对代码进行解释。这至少可以把热点从解释你的时间的方程式中除去。

#9

It's the hotspot compiler at work. AFAIK, the first time it runs the function, runs "interpreted" and the execution path is analyzed, then the JIT compiler can optimize the subsequent function calls.

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

#10

It's most certainly the hotspot compiler. If you're running on 64 bit solaris it defaults to the server VM and hotspot just start optimizing on first execution. On the client VM the code may need to run a few times before hotspot kicks in. (i believe solaris only has the server vm but I may be wrong)

它肯定是hotspot编译器。如果您在64位solaris上运行，它默认为服务器VM和hotspot在第一次执行时就开始优化。在客户端VM上，代码在hotspot开始之前可能需要运行几次。(我认为solaris只有服务器vm，但我可能错了)

#11

See http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.html for how the launcher selects between client and server VM, and what is supported on the different processors and OSes.

请参见http://java.sun.com/javase/6/docs/techtes/guides/vm/server-class.html，了解如何在客户机和服务器VM之间选择启动程序，以及在不同的处理器和操作系统上支持什么。