Warum wird eine Java-Schleife zum ersten Mal LANGSAM ausgeführt?[Sun HotSpot 1.5, sparc]
https://stackoverflow.com/questions/860231
-
21-08-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianFrage
Beim Benchmarking von Java-Code auf einer Solaris SPARC-Box ist mir aufgefallen, dass sie beim ersten Aufruf der Benchmarking-Funktion EXTREM langsam läuft (10-facher Unterschied):
- Zuerst | 1 | 25295.979 ms
- Zweite | 1 | 2256.990 ms
- Dritter | 1 | 2250.575 ms
Warum ist das?Ich vermute den JIT-Compiler. Gibt es eine Möglichkeit, dies zu überprüfen?
Bearbeiten: Angesichts einiger Antworten wollte ich klarstellen, dass dieser Code der einfachste Testfall ist, den ich für dieses Verhalten ausstellen konnte.Mein Ziel ist es nicht, es schnell zu laufen, sondern zu verstehen, was los ist, damit ich es in meinen wirklichen Benchmarks vermeiden kann.
Gelöst: Tom Hawtin hat richtigerweise darauf hingewiesen, dass meine „LANGSAME“ Zeit eigentlich angemessen war.Aufgrund dieser Beobachtung habe ich einen Debugger an den Java-Prozess angehängt.Während der ersten sieht die innere Schleife so aus:
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
Bei den folgenden Iterationen sieht die Schleife folgendermaßen aus:
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
Daher hat HotSpot Speicherzugriffe aus der inneren Schleife entfernt und diese um eine Größenordnung beschleunigt.
Lektion: Rechne nach!Ich hätte Toms Berechnung selbst durchführen sollen.
Benchmark-Java-Code:
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;
}
}
}
Lösung
Einige hässlich, unrealistischer Code (der Stoff, aus Microbenchmarks):
while (counter < 10000000) {
// work
for (int j = 0; j < 100; j++)
counter++;
counter -= 99;
}
Also, was ist diese Weise und wie schnell sollte es laufen.
Die innere Schleife inkrementiert Zähler 100 mal, dann wird der Zähler um 99 dekrementiert wird, um ein Inkrement von 1. Notenzähler ist ein Element mit variabler einer äußeren Klasse, so dass einige Overhead gibt. Dies wird dann 10.000.000 mal laufen. So ist die innere Schleife ausgeführt 1000000000 mal.
Eine Schleife unter Verwendung von Methoden Accessor, rufen sie 25 Zyklen. 1000000000 mal bei 1 GHz, gibt 25s.
Hey, wir vorhergesagt, die SLOW Zeit. Die langsame Zeit ist schnell. Die schnellen Zeiten sind nach der Maßstab in irgendeiner Weise gebrochen wurde - 2,5 Zyklen eine Iteration? Verwenden Sie -Server und Sie können feststellen, es wird noch dumm.
Andere Tipps
Wahrscheinlich handelt es sich um das Laden von Klassen oder die dynamische Verknüpfung nativer Methoden.Wenn Sie Java mit den folgenden JVM-Parametern ausführen (siehe Hier (für eine vollständige Liste) werden Informationen darüber gedruckt, was die Zeit in Anspruch nimmt:
-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation
Um genau herauszufinden, wo jeder der Measure()-Aufrufe beginnt und endet, fügen Sie Initialisierungen einiger neuer Klassen zwischen diesen Methoden als Markierungen hinzu -verbose:class zeigt an, an welcher Stelle in den Protokollen die Markierungsklasse geladen wird.Sehen diese Antwort für eine ähnliche Messung.
Um genau herauszufinden, was Ihr Code macht, habe ich ihn wie folgt geändert:
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 {
}
Schauen Sie sich dann an, wann die JVM diese Mark1 usw. geladen hat.Klassen, hier sind die Ergebnisse.
Beim ersten Aufruf von Measure() wurden insgesamt 85 Klassen geladen, 11 native Methoden dynamisch verknüpft und 5 Methoden JIT-kompiliert:
[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
Beim zweiten Aufruf wurde nur eine Methode JIT-kompiliert:
[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
26 MyBench$MyThread::run (48 bytes)
Second | 1 | 2058,669 ms
Beim dritten Anruf fielen keine weiteren Arbeiten an:
[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third | 1 | 2093,659 ms
Dies wurde unter Windows mit jdk1.6.0_11 ausgeführt, sodass Ihr System die Dinge möglicherweise etwas anders macht.Beispielsweise ist möglicherweise eine dieser Verknüpfungen dynamischer Methoden auf Ihrem System außergewöhnlich langsam.Oder dann ist das Laden der gesamten Klasse langsamer.Sehen Sie sich die Protokolle an und prüfen Sie, ob die Pause ungewöhnlich lang ist oder ob alle Vorgänge gleich langsam sind.
In der Klasse Laden in als Verdächtiger. Klassen sind lazily auf erster Referenz geladen. Also das erste Mal der Code ausgeführt wird, sind Sie wahrscheinlich einige Klassen zum ersten Mal verweisen.
Der beste Weg, um zu überprüfen, ob der JIT-Compiler der Grund für die Beschleunigung in späteren Iterationen ist die Benchmark mit den JIT-Compiler laufen ausgeschaltet. Um dies zu tun, geben Sie die Systemeigenschaft java.compiler=NONE (das Wort „keine“ in Großbuchstaben eingegeben werden müssen).
Die Zeit, Lade tut Klasse kann auch der gebenchmarktes Code verursacht langsamer zum ersten Mal ausgeführt wird. Schließlich gibt es eine nichtdeterministische Verzögerung zwischen Thread.start () aufrufen und den Faden run () -Methode aufgerufen wird.
Sie könnten die Suche nach einem Benchmark-Rahmen zu betrachten. Ein guter Rahmen wird „warm up“ den Code von mehreren Iterationen ausgeführt wird, führen Sie dann mehrere Zeitpunkte mit einer unterschiedlichen Anzahl von Iterationen. Siehe Java Theorie und Praxis: Anatomie eines fehlerhaft-Micro .
Das ist eine interessante Frage. Ich würde die JIT-Compiler vermuten, aber diese sind meine Zahlen:
First | 1 | 2399.233 ms Second | 1 | 2322.359 ms Third | 1 | 2408.342 ms
Möglicherweise Solaris ist etwas komisch mit Fäden tun; haben Sie versucht, mit nThreads = 10 oder so?
Ich schlage vor, Sie machen nThread = Runtime.getRuntime (). AvailableProcessors () Dies wird Ihnen die optimale Anzahl von Threads alle Kerne in dem System zu verwenden.
Sie können versuchen, den JIT ausschalten, um zu sehen, welchen Unterschied es macht.
Sie können die VM erhalten Informationen über Classloading und Zusammenstellung zu protokollieren, versuchen Sie die folgenden VM argumente: -XX: + PrintCompilation -XX: + TraceClassLoading Dies könnte einige weitere Hinweise darauf geben, was unter der Haube passiert.
EDIT: Ich bin nicht sicher, ob diese Optionen in Java arbeiten 1.5 (ich habe sie in 1.6 verwendet wird). Ich werde versuchen, zu überprüfen ... EDIT wieder: Es funktioniert in Java 1.5 (beachten Sie brauchen +, nicht - oder Sie schalten Sie die Option ausgeschaltet ...)
Ich glaube, Sie auch die Nicht-Standard-Option für den Java-Befehl von -Xint verwenden können HotSpot zu deaktivieren und Ihr Code nur interpretiert hat. Dies könnte zumindest HotSpot nimmt aus der Gleichung Ihr Timing für die Interpretation.
Es ist die Hotspot-Compiler bei der Arbeit. AFAIK, das erste Mal die Funktion läuft, läuft „interpretiert“ und der Ausführungspfad analysiert wird, dann kann der JIT-Compiler die nachfolgenden Funktionsaufrufe optimieren.
Es ist sicherlich die Hotspot-Compiler. Wenn Sie sich auf 64-Bit-solaris es standardmäßig auf dem Server VM und Hotspot laufen beginnen gerade auf der ersten Ausführung zu optimieren. Auf dem Client-VM kann der Code benötigt ein paar Mal vor Hotspot-Kicks in laufen. (I solaris nur die Annahme hat, der Server vm aber ich kann falsch sein)
Siehe http: // java. sun.com/javase/6/docs/technotes/guides/vm/server-class.html wie der Launcher wählt zwischen Client und Server VM, und das, was auf den verschiedenen Prozessoren und Betriebssystemen unterstützt wird.
