La prima volta un ciclo di Java è gestito SLOW, perché? [Sun HotSpot 1.5, SPARC]
https://stackoverflow.com/questions/860231
-
21-08-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianDomanda
In analisi comparativa del codice Java su una scatola di Solaris SPARC, ho notato che la prima volta che io chiamo la funzione benchmark si esegue con estrema lentezza (10x differenza):
- Prima | 1 | 25295.979 ms
- Secondo | 1 | 2256.990 ms
- Terzo | 1 | 2250.575 ms
Perché è questo? Ho il sospetto che il compilatore JIT, c'è qualche modo per verificare questo?
Modifica Alla luce di alcune risposte che ho voluto chiarire che questo codice è il più semplice possibile test-case sono riuscito a trovare esibendo questo comportamento. Quindi il mio obiettivo non è quello di ottenere a correre veloce, ma per capire cosa sta succedendo così posso evitarlo in mio vero parametri di riferimento.
Risolto: Tom Hawtin ha giustamente ricordato che il mio tempo "SLOW" era in realtà ragionevole. A seguito di questa osservazione, ho attaccato un debugger al processo Java. Durante la prima, il ciclo interno è simile al seguente:
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
Nelle prossime iterazioni, il ciclo si presenta in questo modo:
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 memoria rimossa accede dal ciclo interno, accelerando l'alto da un ordine di grandezza.
Lezione: Fare la matematica! Avrei dovuto fare il calcolo di Tom me stesso.
Codice di riferimento 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;
}
}
}
Soluzione
Alcuni, codice realistico brutto (roba da microbenchmarks):
while (counter < 10000000) {
// work
for (int j = 0; j < 100; j++)
counter++;
counter -= 99;
}
Allora, qual è questo facendo e quanto velocemente dovrebbe funzionare.
Il ciclo interno incrementa contatore 100 volte, allora il contatore viene decrementato di 99. Quindi, un incremento di 1. contatore Nota è una variabile membro di una classe esterna, in modo certo overhead lì. Questo viene poi eseguito 10.000.000 volte. Così il ciclo interno viene eseguito 1.000.000.000 di volte.
Un ciclo usando accessor metodi, chiamare 25 cicli. 1.000.000.000 di volte a 1 GHz, dà 25s.
Ehi, abbiamo previsto la SLOW di tempo. Il tempo lento è veloce. I tempi rapidi sono dopo il riferimento è stato rotto in qualche modo - 2,5 cicli di iterazione? Usa-server e che si potrebbe trovare diventa ancora più stupido.
Altri suggerimenti
Probabilmente è il caricamento della classe o il collegamento dinamico di metodi nativi. Se si esegue Java con i seguenti parametri JVM (vedi qui per il pieno lista), stamperà le informazioni su ciò che sta prendendo il tempo:
-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation
Per sapere esattamente dove ognuno di misura () le chiamate di inizio e fine, aggiungere inizializzazione di alcune nuove classi tra quei metodi come marcatori, in modo che -verbose:class mostrerà a che punto nei registri di classe marcatore viene caricato. Vedere questa risposta per una misura simile.
Per scoprire esattamente che cosa il codice fa, ho modificato in questo modo:
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 {
}
Poi, cercando in quando la JVM caricato quei ecc classi Mark1, ecco i risultati.
Durante la prima chiamata a misurare (), per un totale di 85 classi sono stati caricati, 11 metodi nativi sono stati collegati dinamicamente e 5 metodi sono stati compilati 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
Durante la seconda chiamata, un solo metodo è stato compilato JIT:
[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
26 MyBench$MyThread::run (48 bytes)
Second | 1 | 2058,669 ms
Nel corso della terza chiamata, non c'era lavoro in più accadendo:
[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third | 1 | 2093,659 ms
Questo è stato eseguito su Windows con jdk1.6.0_11, quindi il sistema potrebbe fare le cose un po 'diverso. Per esempio, forse uno di quei linkings di metodi dinamici è eccezionalmente lento sul vostro sistema. O allora tutta la classe di carico è più lento. Provate a dare un'occhiata ai log, se v'è un insolitamente lunga pausa, o se tutte queste operazioni sono ugualmente lento.
Aggiungi classe di carico come un sospetto. Classi vengono caricate pigramente sul primo riferimento. Così la prima volta che il codice viene eseguito, probabilmente stai riferimento alcune classi per la prima volta.
Il modo migliore per verificare se il compilatore JIT è la ragione per l'aumento di velocità nelle iterazioni successive è quello di eseguire il benchmark con il compilatore JIT disattivato. Per fare questo, specificare la proprietà di sistema java.compiler=NONE (la parola "nessuno" deve essere in maiuscolo).
Il tempo trascorso a fare il caricamento della classe può anche causare il codice parametro di riferimento per l'esecuzione più lenta la prima volta. Infine, v'è un ritardo non deterministico tra chiamare Thread.start () e il metodo run () del thread di essere chiamato.
Si potrebbe prendere in considerazione trovare un framework di riferimento. Un buon quadro sarà "riscaldare" il codice eseguendo diverse iterazioni, quindi fare più sincronizzazioni con un diverso numero di iterazioni. Vedere Java teoria e pratica: Anatomia di un microbenchmark imperfetto .
Questa è una domanda interessante. Avevo il sospetto che il compilatore JIT, ma questi sono i miei numeri:
First | 1 | 2399.233 ms Second | 1 | 2322.359 ms Third | 1 | 2408.342 ms
Forse Solaris sta facendo qualcosa di divertente con fili; hai provato con nThreads = 10 o così?
Vi suggerisco di fare nThread = Runtime.getRuntime (). AvailableProcessors () Questo vi darà il numero ottimale di thread da utilizzare tutti i core del sistema.
È possibile provare a disattivare il JIT per vedere che differenza fa.
È possibile ottenere il VM per registrare le informazioni relative classloading e la compilazione, provare i seguenti argomenti VM: -XX: + PrintCompilation -XX: + TraceClassLoading Questo potrebbe dare alcune ulteriori indizi utili a capire cosa sta succedendo sotto il cofano.
EDIT: Non sono sicuro che queste opzioni funzionano in Java 1.5 (io li ho usato in 1.6). Cercherò di controllare ... EDIT di nuovo: Funziona in Java 1.5 (nota è necessario +, non è - o si attiva l'opzione off ...)
Credo che si può anche utilizzare l'opzione non standard per il comando java di -Xint per disabilitare HotSpot e avere il vostro codice interpretato solo. Questo potrebbe almeno prendere HotSpot fuori dall'equazione per interpretare il vostro tempismo.
E 'il compilatore hotspot al lavoro. AFAIK, la prima volta che viene eseguito la funzione, corre "interpretata" e il percorso di esecuzione viene analizzato, quindi il compilatore JIT può ottimizzare le chiamate di funzione successive.
E 'certamente il compilatore hotspot. Se si sta eseguendo su 64 bit Solaris il valore predefinito è il server VM e hotspot basta iniziare a ottimizzare il prima esecuzione. Sul client VM il codice può essere necessario eseguire un paio di volte prima di calci hotspot a. (Credo Solaris solo ha il server VM, ma posso sbagliarmi)
http: // java. sun.com/javase/6/docs/technotes/guides/vm/server-class.html per come il lanciatore seleziona tra client e server VM, e ciò che è supportato sui diversi processori e sistemi operativi.
