11

Solaris SPARC ボックスでいくつかの Java コードのベンチマークを行っているときに、ベンチマークされた関数を初めて呼び出したときに、実行速度が非常に遅い (10 倍の差) ことに気付きました。

  • 最初 | 1 | 25295.979 ミリ秒
  • セカンド | 1 | 2256.990 ミリ秒
  • サード | 1 | 2250.575 ミリ秒

どうしてこれなの?JIT コンパイラが疑わしいのですが、これを確認する方法はありますか?

編集:いくつかの回答に照らして、このコードがこの動作を示すことができる最も単純なテストケースであることを明確にしたかったのです。したがって、私の目標は、高速に実行することではなく、何が起こっているのかを理解して、実際のベンチマークで回避できるようにすることです。

解決済み: Tom Hawtin は、私の "SLOW" タイムが実際には妥当であると正しく指摘しました。この観察に続いて、デバッガーを 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 は内側のループからメモリ アクセスを削除し、1 桁高速化しました。

レッスン:計算してみよう! トムの計算は自分でやるべきだった.

ベンチマーク 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 秒になります。

ねえ、私たちはSLOW時間を予測しました。遅い時間は速い。速い時間は、ベンチマークが何らかの形で破られた後です-反復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 個のネイティブ メソッドが動的にリンクされ、5 個のメソッドが JIT コンパイルされました。

[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 

2 回目の呼び出しでは、1 つのメソッドのみが JIT コンパイルされました。

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

3 回目の呼び出しでは、追加の作業は行われませんでした。

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

これは jdk1.6.0_11 を使用して Windows で実行されたため、システムによっては少し異なる動作をする可能性があります。たとえば、動的メソッドのリンクの 1 つがシステム上で非常に遅い場合があります。または、すべてのクラスの読み込みが遅くなります。異常に長い一時停止があるかどうか、またはそれらの操作がすべて同じように遅いかどうか、ログを確認してみてください。

于 2009-05-13T21:31:26.107 に答える
3

JIT コンパイラが後の反復での高速化の理由であるかどうかを確認する最善の方法は、JIT コンパイラをオフにしてベンチマークを実行することです。これを行うには、システム プロパティを指定しますjava.compiler=NONE(「none」という単語は大文字にする必要があります)。

クラスの読み込みに時間がかかると、ベンチマーク コードの初回実行速度が遅くなる可能性もあります。最後に、Thread.start() の呼び出しとスレッドの run() メソッドの呼び出しとの間に非決定的な遅延があります。

ベンチマーク フレームワークを見つけることを検討してください。優れたフレームワークは、いくつかの反復を実行することによってコードを「ウォームアップ」し、次に異なる回数の反復で複数のタイミングを実行します。Java の理論と実践: 欠陥のあるマイクロベンチマークの解剖学 を参照してください。

于 2009-05-13T21:04:27.540 に答える
3

クラスの読み込みを容疑者として追加します。クラスは最初の参照で遅延ロードされます。したがって、コードを初めて実行するときは、おそらくいくつかのクラスを初めて参照することになります。

于 2009-05-13T20:35:55.837 に答える
1

-Xint の java コマンドの非標準オプションを使用して HotSpot を無効にし、コードのみを解釈させることもできると思います。これにより、少なくとも、タイミングを解釈するための方程式から HotSpot が除外される可能性があります。

于 2009-05-13T21:11:31.473 に答える
1

クラスローディングとコンパイルに関する情報をログに記録する VM を取得できます。次の VM 引数を試してください: -XX:+PrintCompilation -XX:+TraceClassLoading

EDIT:これらのオプションがJava 1.5で機能するかどうかはわかりません(1.6で使用しました)。確認してみます... もう一度編集:Java 1.5で動作します(-ではなく+が必要であることに注意してください。または、オプションをオフにします...)

于 2009-05-13T20:54:12.173 に答える
1

nThread = Runtime.getRuntime().availableProcessors() を作成することをお勧めします。これにより、システム内のすべてのコアを使用するための最適なスレッド数が得られます。

JIT をオフにしてみて、どのような違いがあるかを確認できます。

于 2009-05-13T20:43:31.457 に答える
1

それは興味深い質問です。私はJITコンパイラを疑っていますが、これらは私の数字です:

最初 | 1 | 2399.233 ミリ秒
セカンド | 1 | 2322.359 ミリ秒
サード | 1 | 2408.342 ミリ秒

おそらく、Solaris はスレッドに関して何かおかしなことをしています。などで試しましnThreads = 10たか?

于 2009-05-13T20:34:22.127 に答える
0

ランチャがクライアント VM とサーバー VM を選択する方法、およびさまざまなプロセッサと OS で何がサポートされているかについては、http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.htmlを参照してください。

于 2009-05-13T21:01:38.637 に答える
0

これは間違いなく hotspot コンパイラです。64ビットのsolarisで実行している場合、デフォルトでサーバーVMとホットスポットが最初の実行時に最適化を開始します。クライアント VM では、ホットスポットが機能する前にコードを数回実行する必要がある場合があります (solaris にはサーバー vm しかない思いますが、間違っている可能性があります) 。

于 2009-05-13T20:47:03.090 に答える
0

これは、作業中のホットスポット コンパイラです。私の知る限り、関数を初めて実行するときに「解釈」されて実行され、実行パスが分析されると、JITコンパイラは後続の関数呼び出しを最適化できます。

于 2009-05-13T20:34:59.943 に答える