La première fois une boucle Java est exécutée LENT, pourquoi? [Sun HotSpot 1.5, sparc]
https://stackoverflow.com/questions/860231
-
21-08-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianQuestion
Dans l'analyse comparative du code Java sur une boîte SPARC Solaris, je remarquai que la première fois que j'appelle la fonction benchmarkée il fonctionne très lentement (10x différence):
- Première | 1 | 25295.979 ms
- Deuxième | 1 | 2256.990 ms
- Troisième | 1 | 2250.575 ms
Pourquoi est-ce? Je soupçonne que le compilateur JIT, est-il possible de le vérifier?
Modifier À la lumière de quelques réponses que je voulais préciser que ce code est le plus simple cas de test possible, je pouvais trouver présenter ce comportement. Donc, mon objectif est de ne pas obtenir à courir vite, mais de comprendre ce qui se passe, je peux l'éviter dans mon vrai points de repère.
Résolu: Tom Hawtin a juste titre que mon temps "SLOW" était en fait raisonnable. Suite à cette observation, je joint un débogueur au processus Java. Au cours de la première, la boucle intérieure ressemble à ceci:
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
Sur les itérations suivantes, la boucle ressemble à ceci:
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 mémoire retirée accède à partir de la boucle intérieure, l'accélérer par un ordre de grandeur.
Leçon: Faites le calcul! Je l'ai fait le calcul de Tom moi-même.
code Java de référence:
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;
}
}
}
La solution
Certains laid, le code irréaliste (la substance de microbenchmarks):
while (counter < 10000000) {
// work
for (int j = 0; j < 100; j++)
counter++;
counter -= 99;
}
Quel est donc ce fait et à quelle vitesse doit-il fonctionner.
La boucle interne incrémente le compteur 100 fois, le compteur est décrémenté par 99. Ainsi, un incrément de 1. Remarque compteur est une variable membre d'une classe externe, de sorte que certains frais généraux là-bas. Ceci est ensuite exécuté 10.000.000 fois. Ainsi, la boucle interne est exécutée 1000000000 fois.
Une boucle à l'aide de méthodes d'accès, appeler 25 cycles. 1000000000 fois à 1 GHz, donne 25s.
Hé, nous avons prédit la LENT Heure. Le temps lent est rapide. Les temps rapides sont après l'indice de référence a été brisée d'une certaine façon - 2,5 cycles d'itération? Utilisez -server et vous trouverez peut-être il y a encore plus stupide.
Autres conseils
C'est probablement le chargement de la classe ou le lien dynamique des méthodes natives. Si vous exécutez Java avec les paramètres JVM suivants (voir ici complète liste), il imprimera des informations sur ce qui est de prendre le temps:
-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation
Pour savoir exactement où chacun de la mesure () appels début et de fin, ajouter initialisations de nouvelles classes entre ces méthodes comme marqueurs, de sorte que montrera à -verbose:class quel moment dans les journaux de la classe de marqueur est chargé. Voir cette réponse pour une mesure similaire.
Pour savoir exactement ce que votre code fait, je l'ai modifié comme suit:
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 {
}
Ensuite, en regardant lorsque la machine virtuelle Java chargée ces Mark1 etc. cours, voici les résultats.
Au cours du premier appel à mesurer (), un total de 85 catégories ont été chargés, 11 méthodes natives ont été liés dynamiquement et 5 méthodes ont été compilées 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
Au cours du deuxième appel, a été JIT compilé une seule méthode:
[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
26 MyBench$MyThread::run (48 bytes)
Second | 1 | 2058,669 ms
Au cours du troisième appel, il n'y avait pas de travail supplémentaire qui se passe:
[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third | 1 | 2093,659 ms
Ceci a été exécuté sur Windows avec jdk1.6.0_11, de sorte que votre système peut faire des choses un peu différemment. Par exemple, peut-être un de ces chaînages de méthodes dynamiques est extrêmement lent sur votre système. Ou alors tout le chargement de classe est plus lente. Essayez d'avoir un oeil sur les journaux, s'il y a une pause anormalement longue, ou si toutes ces opérations sont également lents.
Ajoutez le chargement des classes en tant que suspect. Les classes sont chargées paresseusement sur la première référence. La première fois que le code est exécuté, vous faites référence probablement des cours pour la première fois.
La meilleure façon de vérifier si le compilateur JIT est la raison de l'accélération dans les itérations ultérieures est d'exécuter la référence avec le compilateur JIT désactivé. Pour ce faire, spécifiez la propriété système java.compiler=NONE (le mot « aucun » doit être en majuscules).
Le temps passé à faire le chargement de classe peut également provoquer le code benchmarkée à fonctionner plus lentement la première fois. Enfin, il y a un délai entre nondéterministe appelant la méthode Thread.start () et run () du thread appelé.
Vous voudrez peut-être envisager de trouver un cadre de référence. Un bon cadre sera « réchauffer » le code en exécutant plusieurs itérations, puis effectuez plusieurs synchronisations avec un nombre différent d'itérations. Voir Java et pratique: Anatomie d'un microbenchmark défectueux.
C'est une question intéressante. Je soupçonne que le compilateur JIT, mais ce sont mes chiffres:
First | 1 | 2399.233 ms Second | 1 | 2322.359 ms Third | 1 | 2408.342 ms
Peut-être Solaris est en train de faire quelque chose de drôle avec des fils; Avez-vous essayé avec ou si nThreads = 10?
Je vous suggère de faire nThread = Runtime.getRuntime (). AvailableProcessors () Cela vous donnera le nombre optimal de threads à utiliser tous les coeurs dans votre système.
Vous pouvez essayer de désactiver le JIT pour voir quelle différence cela fait.
Vous pouvez obtenir la machine virtuelle pour enregistrer des informations sur classloading et la compilation, essayez les args VM suivantes: -XX: + PrintCompilation -XX: + TraceClassLoading Cela pourrait donner quelques indices supplémentaires quant à ce qui se passe sous le capot.
EDIT: Je ne suis pas sûr que ces options fonctionnent en Java 1.5 (je les ai utilisés dans 1.6). Je vais essayer de vérifier ... EDIT à nouveau: Il fonctionne en Java 1.5 (notez que vous avez besoin +, non - ou vous désactivez l'option ...)
Je crois que vous pouvez également utiliser l'option non standard pour la commande java de -Xint pour désactiver HotSpot et que votre code interprété uniquement. Cela pourrait au moins prendre HotSpot de l'équation pour interpréter votre timing.
Il est le compilateur hotspot au travail. Autant que je sache, la première fois qu'il exécute la fonction, exécute « interprété » et le chemin d'exécution est analysée, le compilateur JIT peut optimiser les appels de fonctions ultérieures.
Il est très certainement le compilateur hotspot. Si vous utilisez sur 64 bits solaris il faut par défaut du serveur VM et hotspot juste commencer à optimiser à la première exécution. Sur le client VM le code peut avoir besoin d'exécuter plusieurs fois avant coups de pied du point d'accès dans. (Je crois que solaris a le serveur vm mais je peux me tromper)
Voir http: // java. sun.com/javase/6/docs/technotes/guides/vm/server-class.html comment le lanceur sélectionne entre VM de client et le serveur, et ce qui est pris en charge sur les différents processeurs et systèmes d'exploitation.
