Primeira vez que um loop de Java é executado SLOW, porquê? [Sun HotSpot 1,5, sparc]
https://stackoverflow.com/questions/860231
-
21-08-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianPergunta
Na análise comparativa algum código Java em uma caixa de Solaris SPARC, notei que a primeira vez que eu chamar a função aferido corre muito lentamente (10x diferença):
- Primeiro | 1 | 25295.979 ms
- Em segundo lugar | 1 | 2256.990 ms
- Third | 1 | 2250.575 ms
Por que isso? Eu suspeito que o compilador JIT, existe alguma maneira de verificar isso?
Editar: À luz de algumas respostas que eu queria esclarecer que este código é o mais simples possível de casos de teste que eu poderia encontrar exibindo esse comportamento. Então, meu objetivo não é obter -lo para correr rápido, mas para entender o que está acontecendo para que eu possa evitá-lo no meu verdadeiro benchmarks.
Resolvido: Tom Hawtin corretamente apontou que o meu tempo "SLOW" era na verdade razoável. Seguindo essa observação, I anexa um depurador ao processo de Java. Durante o primeiro, o loop olhares internos como este:
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
Em iterações seguintes, os olhares loop como este:
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
Assim HotSpot removido acessos à memória do loop interno, acelerando-a por uma ordem de magnitude.
Lição: Faça as contas! Eu deveria ter feito o cálculo do Tom mim mesmo.
Referência de código 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;
}
}
}
Solução
Alguns, código irrealista feio (o material de microbenchmarks):
while (counter < 10000000) {
// work
for (int j = 0; j < 100; j++)
counter++;
counter -= 99;
}
Assim que é esta fazendo e quão rápido ele deve ser executado.
Os incrementos laço interno contra 100 vezes, em seguida, o contador é diminuído por 99. Assim, um incremento de 1. Nota contador é uma variável membro de uma classe externa, de modo algum sobrecarga lá. Este é então executado 10.000.000 vezes. Assim, o loop interno é executado 1.000.000.000 de vezes.
Um loop usando a métodos de acesso, chamá-lo de 25 ciclos. 1.000.000.000 de vezes em 1 GHz, dá 25s.
Ei, nós previu o SLOW tempo. O tempo lento é rápido. Os tempos rápidos são após o benchmark foi quebrado de alguma forma - 2,5 ciclos uma iteração? Use -server e você pode encontrá-lo fica ainda mais tolo.
Outras dicas
Provavelmente é o carregamento de classe ou dinâmico ligando de métodos nativos. Se você executar Java com os seguintes parâmetros JVM (ver aqui para o pleno lista), ele irá imprimir informações sobre o que está tomando o tempo:
-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation
Para saber exatamente onde cada da medida () chamadas de início e fim, adicione inicializações de algumas novas classes entre esses métodos como marcadores, de modo que -verbose:class irá mostrar em que ponto nos logs da classe marcador é carregado. Veja esta resposta para uma medida similar.
Para saber exatamente o que seu código faz, eu modifiquei-lo assim:
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 {
}
Então, olhando para quando o JVM carregado essas classes Mark1 etc., aqui estão os resultados.
Durante a primeira chamada de medida (), um total de 85 classes de foram carregados, 11 métodos nativos foram ligados dinamicamente e 5 métodos foram compilados 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 a segunda chamada, apenas um método foi JIT compilado:
[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
26 MyBench$MyThread::run (48 bytes)
Second | 1 | 2058,669 ms
Durante a terceira chamada, não havia nenhum trabalho adicional acontecendo:
[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third | 1 | 2093,659 ms
Isto foi executado no Windows com jdk1.6.0_11, assim que seu sistema pode fazer as coisas um pouco diferente. Por exemplo, talvez uma daquelas ligações de métodos dinâmicos é excepcionalmente lento em seu sistema. Ou então todo o carregamento de classe é mais lento. Tente ter um olhar para os logs, se há uma invulgarmente longa pausa, ou se todas essas operações são igualmente lento.
Adicionar carregamento de classe como um suspeito. As classes são carregados preguiçosamente na primeira referência. Então, pela primeira vez, o código é executado, você provavelmente está referenciando algumas aulas pela primeira vez.
A melhor maneira de verificar se o compilador JIT é a razão para o aumento de velocidade em iterações posteriores é executar o benchmark com o compilador JIT desligado. Para fazer isso, especifique o java.compiler=NONE propriedade do sistema (a palavra "none" deve estar em letras maiúsculas).
O tempo gasto para fazer o carregamento de classe também pode causar o código aferido para executar mais lento o primeiro tempo. Finalmente, há um atraso nondeterministic entre chamar Thread.start () e método de execução da Thread () sendo chamado.
Você pode querer considerar a busca de um quadro de referência. Uma estrutura boa vontade "aquecer" o código executando várias iterações, em seguida, fazer várias horários com um número diferente de iterações. Consulte Java e prática: Anatomia de um microbenchmark falho .
Essa é uma pergunta interessante. Eu suspeito que o compilador JIT, mas estes são os meus números:
First | 1 | 2399.233 ms Second | 1 | 2322.359 ms Third | 1 | 2408.342 ms
Possivelmente Solaris está fazendo algo engraçado com fios; você já tentou com nThreads = 10 ou assim?
Eu sugiro que você faça nThread = Runtime.getRuntime (). AvailableProcessors () Isto lhe dará o número ideal de threads a ser usado todos os núcleos em seu sistema.
Você pode tentar desligar o JIT para ver que diferença faz.
Você pode obter o VM para registrar informações sobre carregamento de classe e compilação, tente as seguintes args VM: -XX: + PrintCompilation -XX: + TraceClassLoading Isso pode lhe dar mais algumas pistas sobre o que está acontecendo sob o capô.
EDIT: Eu não tenho certeza essas opções funcionam em java 1.5 (eu usei-los em 1.6). Vou tentar verificar ... EDIT novamente: Ele funciona em java 1.5 (nota que você precisa +, não -, ou você desativar a opção ...)
Eu acredito que você também pode usar a opção não-padrão para o comando java de -Xint para desativar HotSpot e ter o seu código só interpretada. Isso poderia pelo menos ter HotSpot fora da equação para interpretar o seu timing.
É o compilador hotspot no trabalho. AFAIK, a primeira vez que executa a função, corre "interpretado" e o caminho de execução é analisada, em seguida, o compilador JIT pode otimizar as chamadas de função subseqüentes.
É certamente o compilador hotspot. Se você estiver executando em 64 bits solaris que o padrão é o servidor VM e hotspot apenas começar a otimizar na primeira execução. No cliente VM o código seja necessário executar algumas vezes antes chutes hotspot em. (Eu acredito única solaris tem do vm servidor, mas posso estar errado)
Consulte http: // java. sun.com/javase/6/docs/technotes/guides/vm/server-class.html para saber como as seleciona lançador entre cliente e servidor VM, eo que é compatível com os diferentes processadores e sistemas operacionais.
