Aplicação lenta, JVM frequente trava com configurações de CPU única e Java 12+

24

Temos um aplicativo cliente (com mais de 10 anos de desenvolvimento). Seu JDK foi atualizado do OpenJDK 11 para o OpenJDK 14 recentemente. Nas configurações de Windows 10 de CPU única (com hyperthreading desativado) (e dentro de máquinas VirtualBox com apenas uma CPU disponível), o aplicativo é iniciado lentamente em comparação ao Java 11. Além disso, ele usa 100% da CPU na maioria das vezes. Também podemos reproduzir o problema ao definir a afinidade do processador para apenas uma CPU ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Algumas medidas ao iniciar o aplicativo e fazer uma consulta com interação manual mínima na minha máquina VirtualBox:

  • OpenJDK 11.0.2: 36 segundos
  • OpenJDK 13.0.2: ~ 1.5 minutos
  • OpenJDK 13.0.2 com -XX:-UseBiasedLocking: 46 segundos
  • OpenJDK 13.0.2 com -XX:-ThreadLocalHandshakes: 40 segundos
  • OpenJDK 14: 5-6 minutos
  • OpenJDK 14 com -XX:-UseBiasedLocking: 3-3,5 minutos
  • OpenJDK 15 EA Build 20: ~ 4,5 minutos

Somente o JDK usado (e as opções mencionadas) foi alterado. ( -XX:-ThreadLocalHandshakesnão está disponível no Java 14.)

Tentamos registrar o que o JDK 14 faz -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Contar as linhas de log a cada segundo parece bastante suave com o OpenJDK 11.0.2:

$ cat jdk11-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
  30710 0
  44012 1
  55461 2
  55974 3
  27182 4
  41292 5
  43796 6
  51889 7
  54170 8
  58850 9
  51422 10
  44378 11
  41405 12
  53589 13
  41696 14
  29526 15
   2350 16
  50228 17
  62623 18
  42684 19
  45045 20

Por outro lado, o OpenJDK 14 parece ter períodos tranquilos interessantes:

$ cat jdk14-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
   7726 0
   1715 5
  10744 6
   4341 11
  42792 12
  45979 13
  38783 14
  17253 21
  34747 22
   1025 28
   2079 33
   2398 39
   3016 44

Então, o que está acontecendo entre os segundos 1-4, 7-10 e 14-20?

...
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerFactory$1 java.lang.Thread CleanerFactory.java:45
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerImpl java.lang.Thread CleanerImpl.java:117
[0.350s][7248][info ][biasedlocking        ] Aligned thread 0x000000001727e010 to 0x000000001727e800
[0.350s][7248][info ][os,thread            ] Thread started (tid: 2944, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.350s][6884][info ][os,thread            ] Thread is alive (tid: 6884).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack dimensions: 0x00000000175b0000-0x00000000176b0000 (1024k).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack guard pages activated: 0x00000000175b0000-0x00000000175b4000.
[0.350s][7248][debug][thread,smr           ] tid=7248: Threads::add: new ThreadsList=0x0000000017254500
[0.350s][7248][debug][thread,smr           ] tid=7248: ThreadsSMRSupport::free_list: threads=0x0000000017253d50 is freed.
[0.350s][2944][info ][os,thread            ] Thread is alive (tid: 2944).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack dimensions: 0x00000000177b0000-0x00000000178b0000 (1024k).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack guard pages activated: 0x00000000177b0000-0x00000000177b4000.
[0.351s][2944][debug][class,resolve        ] java.lang.Thread java.lang.Runnable Thread.java:832
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.misc.InnocuousThread CleanerImpl.java:135
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.ref.PhantomCleanable CleanerImpl.java:138
[0.351s][2944][info ][biasedlocking,handshake] JavaThread 0x000000001727e800 handshaking JavaThread 0x000000000286d800 to revoke object 0x00000000c0087f78
[0.351s][2944][debug][vmthread               ] Adding VM operation: HandshakeOneThread
[0.351s][6708][debug][vmthread               ] Evaluating non-safepoint VM operation: HandshakeOneThread
[0.351s][6708][debug][vmoperation            ] begin VM_Operation (0x00000000178af250): HandshakeOneThread, mode: no safepoint, requested by thread 0x000000001727e800

# no log until 5.723s

[5.723s][7248][info ][biasedlocking          ]   Revoked bias of currently-unlocked object
[5.723s][7248][debug][handshake,task         ] Operation: RevokeOneBias for thread 0x000000000286d800, is_vm_thread: false, completed in 94800 ns
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.lang.ref.Cleaner ZipFile.java:715
[5.723s][7248][debug][class,resolve          ] java.lang.ref.Cleaner jdk.internal.ref.CleanerImpl$PhantomCleanableRef Cleaner.java:220
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.util.WeakHashMap ZipFile.java:716
...

A segunda pausa um pouco mais tarde:

...
[6.246s][7248][info ][class,load              ] java.awt.Graphics source: jrt:/java.desktop
[6.246s][7248][debug][class,load              ]  klass: 0x0000000100081a00 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 5625 checksum: 0025818f
[6.246s][7248][debug][class,resolve           ] java.awt.Graphics java.lang.Object (super)
[6.246s][7248][info ][class,loader,constraints] updating constraint for name java/awt/Graphics, loader 'bootstrap', by setting class object
[6.246s][7248][debug][jit,compilation         ]   19       4       java.lang.Object::<init> (1 bytes)   made not entrant
[6.246s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1400 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 700 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 800 ns

# no log until 11.783s

[11.783s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 6300 ns
[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[11.783s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[11.783s][7248][debug][protectiondomain        ] Checking package access
[11.783s][7248][debug][protectiondomain        ] class loader: a 'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x00000000c0058628} protection domain: a 'java/security/ProtectionDomain'{0x00000000c058b948} loading: 'java/awt/Graphics'
[11.783s][7248][debug][protectiondomain        ] granted
[11.783s][7248][debug][class,resolve           ] sun.launcher.LauncherHelper java.awt.Graphics LauncherHelper.java:816 (reflection)
[11.783s][7248][debug][class,resolve           ] jdk.internal.reflect.Reflection [Ljava.lang.reflect.Method; Reflection.java:300
[11.783s][7248][debug][class,preorder          ] java.lang.PublicMethods$MethodList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
...

Então o terceiro:

...
[14.578s][7248][debug][class,preorder          ] java.lang.InheritableThreadLocal source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[14.578s][7248][info ][class,load              ] java.lang.InheritableThreadLocal source: jrt:/java.base
[14.578s][7248][debug][class,load              ]  klass: 0x0000000100124740 super: 0x0000000100021a18 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 1338 checksum: 8013ed55
[14.578s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal (super)
[14.578s][7248][debug][jit,compilation         ]  699       3       java.lang.ThreadLocal::get (38 bytes)   made not entrant
[14.578s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1600 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 900 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 0 ns
[14.579s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 900 ns

# no log until 21.455s

[21.455s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 12100 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns
[21.455s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[21.455s][7248][debug][class,resolve           ] sun.security.jca.Providers java.lang.InheritableThreadLocal Providers.java:39
[21.455s][7248][info ][class,init              ] 1251 Initializing 'java/lang/InheritableThreadLocal'(no method) (0x0000000100124740)
[21.455s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal InheritableThreadLocal.java:57
[21.456s][7248][debug][class,preorder          ] sun.security.jca.ProviderList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[21.456s][7248][info ][class,load              ] sun.security.jca.ProviderList source: jrt:/java.base
[21.456s][7248][debug][class,load              ]  klass: 0x00000001001249a8 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 11522 checksum: bdc239d2
[21.456s][7248][debug][class,resolve           ] sun.security.jca.ProviderList java.lang.Object (super)
...

As duas linhas a seguir parecem interessantes:

[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns

É normal que esses apertos de mão levem 5,5 e 6,8 segundos?

Eu experimentei o mesmo abrandamento (e logs semelhantes) com o aplicativo demo update4j (que não tem nenhuma relação com nosso aplicativo) executando com este comando:

Z:\swing>\jdk-14\bin\java -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50 \
    -jar update4j-1.4.5.jar --remote http://docs.update4j.org/demo/setup.xml

O que devo procurar para tornar nosso aplicativo mais rápido novamente nas configurações de Windows 10 de CPU única? Posso corrigir isso alterando algo em nosso aplicativo ou adicionando argumentos da JVM?

Isso é um bug do JDK, devo denunciá-lo?

atualização 2020-04-25:

Tanto quanto vejo, os arquivos de log também contêm logs do GC. Estes são os primeiros logs do GC:

$ cat app.txt.00 | grep "\[gc"
[0.016s][7248][debug][gc,heap          ] Minimum heap 8388608  Initial heap 60817408  Maximum heap 1073741824
[0.017s][7248][info ][gc,heap,coops    ] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit
[0.018s][7248][info ][gc               ] Using Serial
[22.863s][6708][info ][gc,start                ] GC(0) Pause Young (Allocation Failure)
[22.863s][6708][debug][gc,heap                 ] GC(0) Heap before GC invocations=0 (full 0): def new generation   total 17856K, used 15936K [0x00000000c0000000, 0x00000000c1350000, 0x00000000d5550000)
...

Infelizmente, isso não parece relacionado, pois começa após a terceira pausa.

atualização 2020-04-26:

Com o OpenJDK 14, o aplicativo usa 100% da CPU na minha máquina VirtualBox (CPU única) (executando em uma CPU i7-6600U). A máquina virtual possui 3,5 GB de RAM. De acordo com o Gerenciador de tarefas, 40% + é gratuito e a atividade do disco é 0% (acho que isso não significa troca). Adicionar outra CPU à máquina virtual (e ativar o hyperthreading para máquinas físicas) torna o aplicativo rápido o suficiente novamente. Só me pergunto, foi uma troca intencional durante o desenvolvimento do JDK a perda de desempenho em máquinas (raras) de CPU única para acelerar a JVM em CPUs multicore / hyper-threading?

java hang java-14 palacsint
fonte
3
Será que -Xlog:all=debugactivar o registo GC? Esse seria meu primeiro palpite para qualquer pausa.
kichik 24/04
Você tentou executar com um criador de perfil e comparou os resultados? Eu acho que seria a coisa natural a fazer.
Axel
11
Também verifique as mensagens do sistema Windows, tente uma compilação diferente para o jdk 14. Se tudo mais falhar, aumente como um problema?
Khanna111
11
@ Yan.F: O OpenJDK 11 não será suportado para sempre, é hora de preparar os novos lançamentos e bugs. Além disso, parece um bug do JDK - que pode ser corrigido ou não, mas também pode ajudar os outros. Enfim, para mim é principalmente curiosidade. Por outro lado, agora eu gostaria de dizer aos nossos clientes como requisitos mínimos do sistema do nosso aplicativo.
palacsint 26/04
11
@ Khanna111: Sim, acabei de escrever como resposta.
palacsint

Respostas:

6

Pela minha experiência, os problemas de desempenho com JDKs estão relacionados principalmente a um dos seguintes:

  • Compilação JIT
  • Configuração da VM (tamanhos de heap)
  • Algoritmo GC
  • Alterações na JVM / JDK que quebram bons aplicativos em execução conhecidos
  • (Ah, e eu esqueci de mencionar o carregamento da classe ...)

Se você acabou de usar a configuração padrão da JVM desde o OpenJDK11, talvez defina algumas das opções mais importantes para valores fixos, como GC, tamanho da pilha, etc.

Talvez alguma ferramenta de análise gráfica possa ajudar a rastrear seu problema. Como Retrace, AppDynamics ou FlightRecorder e similares. Eles fornecem mais visão geral sobre o estado geral de heap, ciclos gc, RAM, threads, carga da CPU e assim por diante em um determinado momento do que os arquivos de log poderiam fornecer.

Entendo corretamente que seu aplicativo grava cerca de 30710 linhas no log no primeiro segundo de execução (no OpenJDK11)? Por que "apenas" está escrevendo cerca de 7 mil linhas no OpenJDK14 no primeiro segundo? Isso parece uma enorme diferença para um aplicativo que acabou de ser iniciado em JVMs diferentes para mim ... Você tem certeza de que não há, por exemplo, grandes quantidades de stacktraces de Exception despejados no log?
Os outros números são ainda mais altos às vezes, então talvez as desacelerações estejam relacionadas ao registro de exceções? Ou até mesmo trocar, se a RAM ficar baixa?
Na verdade, estou pensando que, se um aplicativo não gravar nada no log, isso é um sinal de bom funcionamento sem problemas (a menos que esteja congelado totalmente nesse período). O que está acontecendo dos segundos 12 a 22 (no caso OpenJDK14 aqui) é o que mais me preocuparia ... as linhas registradas atravessam o telhado ... por quê ? ? (bem, talvez seja o gc chutando no segundo 22 e faz uma tabula rasa que resolve algumas coisas ...?)
E depois o registro diminui para todos os tempos, valores baixos de cerca de 1-2k linhas ... qual é a razão para isso

Outra coisa pode ser a sua declaração sobre máquinas com "CPU única". Isso implica também em "núcleo único" (Idk, talvez seu software seja adaptado em hardware herdado ou algo assim)? E as VMs de "CPU única" estão sendo executadas nessas máquinas? Mas suponho que estou errado sobre essas suposições, já que quase todas as CPUs são multicore hoje em dia ... mas eu investigaria talvez um problema de problema de multithreading (deadlock).

Antares
fonte
2
Por favor, não use assinaturas ou slogans em suas postagens, o repetitivo "GL e HF" é considerado ruído e uma distração do conteúdo de sua postagem aqui. Consulte meta.stackexchange.com/help/behavior para obter mais informações.
meagar
11
"Entendo corretamente que seu aplicativo grava cerca de 30710 linhas no log no primeiro segundo de execução (no OpenJDK11)?" - Sim, você está certo.
palacsint 26/04
11
"Você tem certeza de que não há, por exemplo, grandes quantidades de rastreamentos de exceções despejados no log?" - O log está limpo, não encontrei nada de estranho por lá, o aplicativo funciona corretamente (exceto pelo fato de ser executado muito, muito devagar).
palacsint 26/04
11
O GC está chutando no 22º segundo e o aplicativo permanece lento depois disso. Eu também atualizei a pergunta. Observe que o aplicativo de demonstração update4j também tem o mesmo problema. Obrigado pela resposta!
palacsint 26/04
11
30k + linhas de log em um segundo é enorme ... você não concorda? Eu realmente me pergunto o que poderia ser útil para fazer logon para aceitar essa grande quantidade de linhas de log em tão pouco tempo ... Você tentou desativar completamente o log e criar um perfil do aplicativo nesse modo? (Estou curioso, mas talvez o registro realmente não tenha impacto, como você sugere com o comportamento do update4j)
Antares
5

Como ele usa 100% da CPU "na maioria das vezes" e leva 10 vezes mais (!) Com o Java 14, significa que você está desperdiçando 90% da sua CPU no Java 14.

A falta de espaço na pilha pode fazer isso, pois você passa muito tempo no GC, mas parece que descartou isso.

Percebo que você está aprimorando a opção de bloqueio parcial e isso faz uma diferença significativa. Isso me diz que talvez seu programa faça muito trabalho simultâneo em vários threads. É possível que seu programa tenha um bug de simultaneidade que apareça no Java 14, mas não no Java 10. Isso também pode explicar por que a adição de outra CPU o torna mais do que o dobro da velocidade.

Os erros de simultaneidade geralmente aparecem apenas quando você não tem sorte, e o gatilho pode realmente ter sido qualquer coisa, como uma alteração na organização do hashmap, etc.

Primeiro, se for possível, verifique se existem loops que podem estar ocupados - esperando, em vez de dormir.

Em seguida, execute um criador de perfil no modo de amostragem (o jvisualvm funcionará) e procure métodos que estão gastando muito mais% do tempo total do que deveriam. Como seu desempenho é reduzido em um fator de 10, qualquer problema deve realmente surgir.

Matt Timmermans
fonte
O bloqueio parcial era necessário no passado, mas hoje em dia não tanto, e propõe-se que seja desativado por padrão e posteriormente removido: openjdk.java.net/jeps/374
JohannesB
3

TL; DR : É uma regressão do OpenJDK.

Não fiz isso, mas pude reproduzir o problema com um simples olá mundo:

public class Main {
    public static void main(String[] args) {
        System.out.println("Hello world");
    }
}

Eu usei esses dois arquivos em lotes:

main-1cpu.bat, que limita o javaprocesso a apenas uma CPU:

c:\windows\system32\cmd.exe /C start /affinity 1 \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-1cpu.txt:uptime,tid,level,tags:filecount=50 \
    Main

main-full.bat, o javaprocesso pode usar as duas CPUs:

c:\windows\system32\cmd.exe /C start /affinity FF \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-full.txt:uptime,tid,level,tags:filecount=50 \
    Main

(As diferenças são o affinityvalor e o nome do arquivo de log. Eu o agrupei para facilitar a leitura, mas com\ provavelmente não funciona no Windows.)

Algumas medidas no Windows 10 x64 no VirtualBox (com duas CPUs):

PS Z:\main> Measure-Command { .\main-1cpu.bat }

...    
TotalSeconds      : 7.0203455
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5751352
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5585384
...


PS Z:\main> Measure-Command { .\main-1cpu.bat }

...
TotalSeconds      : 23.6482685
...

Os registros de rastreamento produzidos contêm pausas semelhantes que você pode ver na pergunta.

Corrida Main sem registros de rastreamento é mais rápida, mas a diferença ainda pode ser observada entre a versão de uma CPU e duas CPUs: ~ 4-7 segundos vs. ~ 400 ms.

Enviei essas descobertas para a lista de email hotspot-dev @ openjdk e os desenvolvedores confirmaram que isso é algo que o JDK poderia lidar melhor . Você também pode encontrar supostas correções no tópico. Espero que seja corrigido no OpenJDK 15.

palacsint
fonte
2

Essa é uma questão interessante e exigiria uma quantidade indeterminada de esforço para reduzi-la, uma vez que existem muitas permutações e combinações que precisam ser testadas e os dados coletados e agrupados.

Parece que até o momento não há nenhuma solução para isso. Talvez isso precise ser escalado.

EDIÇÃO 2: Como "ThreadLocalHandshakes" foi descontinuado e podemos assumir que o bloqueio é contestado, sugira tentar sem "UseBiasingLocking" para acelerar esse cenário.

No entanto, existem algumas sugestões para coletar mais dados e tentar isolar o problema.

  1. Aloque mais de um núcleo [vejo que você tentou e o problema desaparece. Parece ser um problema com a execução de um thread que impede outros. Veja no 7 abaixo)
  2. Aloque mais heap (talvez as demandas da v14 sejam mais do que as dos jdks anteriores)
  3. Aloque mais memória para o Win 10 VB.
  4. Verifique as mensagens do sistema OS (Win 10 no seu caso)
  5. Execute-o em um Win 10 não virtualizado.
  6. Experimente uma compilação diferente do jdk 14
  7. Faça um despejo de encadeamento a cada (ou perfil) poucos intervalos de tempo. Analise qual thread está sendo executado exclusivamente. Talvez haja uma configuração para o compartilhamento de tempo eqüitativo. Talvez haja um encadeamento de prioridade mais alta em execução. O que é esse fio e o que ele está fazendo? No linux, você pode declarar os processos leves (threads) associados a um processo e seu estado em tempo real. Algo semelhante no Win 10?
  8. Utilização do CPU? 100% ou menos? Restringido por CPU ou mem? CPU 100% em threads de serviço? Qual thread de serviço?
  9. Você definiu explicitamente um GC algo?

Testemunhei pessoalmente problemas em versões relacionadas ao GC, redimensionamento de heap, problemas com contêineres virtualizados e assim por diante.

Acho que não há uma resposta fácil, especialmente porque essa pergunta existe há algum tempo. Mas podemos tentar tudo de melhor e informar-nos qual é o resultado de algumas dessas etapas de isolamento.

EDIT 1: a partir da pergunta atualizada, parece estar relacionada a um GC ou outro encadeamento de serviço que assume o núcleo único de maneira não equitativa (Handshakes de Thread-Local)?

Khanna111
fonte
Adicionando um núcleo de CPU extra usado para acionar a comutação da ergonomia Java em sistemas de 32 bits de um cliente para uma classe de servidor vm com GC diferente e Compilação em Camadas, se esse ainda for o caso, pode explicar diferenças repentinas no desempenho e no uso da memória, sim JVM desempenho é complicado 😁
JohannesB
3
A ergonomia Java (configurações padrão) ainda é diferente para 1 CPU (por exemplo: -XX: + UseSerialGC) ou 2 CPU (por exemplo: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Mas depois de verificar com -XX: + PrintFlagsFinal que ajustei todos os parâmetros para o mesmo ou em execução update4j ainda era extremamente lento para iniciar com apenas uma em vez de 2 CPUs com cmd.exe / C start / affinity 0x1 (mas extremamente rápido com 0x3 - usando, portanto, 2 cpus (1 + 10 binário)). Confirmei que não podemos culpar nenhum coletor de lixo usando o Epsilon GC, projetado para evitar sobrecarga do GC. No entanto, o TieredCompilation está ativado
JohannesB
Eu vejo. Com o Epsilon GC, parece que foi tão lento. Nesse caso, os status e despejos de threads para avaliar onde ficam presos podem ser uma maneira. Tanto no mundo Java quanto no mundo OS (Linux, se bem me lembro, era gcore)
Khanna111 27/04
1

Tenha cuidado com o registro para desacelerar os discos, pois o aplicativo será mais lento:

https://engineering.linkedin.com/blog/2016/02/eliminating-large-jvm-gc-pauses-caused-by-background-io-traffic

Mas não parece ser a causa do problema, pois a CPU ainda está ocupada e você não precisa esperar que todos os threads cheguem a um ponto seguro, graças ao handshake local do thread: https: // openjdk. java.net/jeps/312

Além disso, não está diretamente relacionado ao problema que você tem, mas de maneira mais geral, se você quiser obter mais desempenho do seu hardware durante o tempo de inicialização, consulte o AppCDS (compartilhamento de dados de classe):

https://blog.codefx.org/java/application-class-data-sharing/

JohannesB
fonte