Application lente, JVM fréquent se bloque avec des configurations à processeur unique et Java 12+

24

Nous avons une application client (avec plus de 10 ans de développement). Son JDK a été récemment mis à niveau d'OpenJDK 11 vers OpenJDK 14. Sur les configurations Windows 10 à processeur unique (hyper-threading désactivé) (et à l'intérieur des machines VirtualBox avec un seul processeur disponible), l'application démarre assez lentement par rapport à Java 11. De plus, elle utilise 100% de CPU la plupart du temps. Nous pourrions également reproduire le problème en définissant l'affinité du processeur sur un seul processeur ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Quelques mesures avec le démarrage de l'application et l'exécution d'une requête avec une interaction manuelle minimale dans ma machine VirtualBox:

  • OpenJDK 11.0.2: 36 secondes
  • OpenJDK 13.0.2: ~ 1,5 minutes
  • OpenJDK 13.0.2 avec -XX:-UseBiasedLocking: 46 secondes
  • OpenJDK 13.0.2 avec -XX:-ThreadLocalHandshakes: 40 secondes
  • OpenJDK 14: 5-6 minutes
  • OpenJDK 14 avec -XX:-UseBiasedLocking: 3-3,5 minutes
  • OpenJDK 15 EA Build 20: ~ 4,5 minutes

Seul le JDK utilisé (et les options mentionnées) ont été modifiés. ( -XX:-ThreadLocalHandshakesn'est pas disponible dans Java 14.)

Nous avons essayé de consigner ce que fait le JDK 14 -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Compter les lignes de journal pour chaque seconde semble assez simple avec 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

En revanche, OpenJDK 14 semble avoir des périodes de silence intéressantes:

$ 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

Alors, que se passe-t-il entre les secondes 1-4, 7-10 et 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
...

La deuxième pause un peu plus tard:

...
[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
...

Puis le troisième:

...
[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)
...

Les deux lignes suivantes semblent intéressantes:

[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

Est-ce normal que ces poignées de main aient pris 5,5 et 6,8 secondes?

J'ai connu le même ralentissement (et des journaux similaires) avec l' application de démonstration update4j (qui n'a aucun lien avec notre application) exécutée avec cette commande:

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

Que dois-je rechercher pour accélérer à nouveau notre application sur les configurations Windows 10 à processeur unique? Puis-je résoudre ce problème en modifiant quelque chose dans notre application ou en ajoutant des arguments JVM?

Est-ce un bug JDK, dois-je le signaler?

mise à jour 2020-04-25:

Pour autant que je vois, les fichiers journaux contiennent également des journaux GC. Ce sont les premiers journaux 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)
...

Malheureusement, il ne semble pas lié car il commence après la troisième pause.

mise à jour 2020-04-26:

Avec OpenJDK 14, l'application utilise 100% de CPU dans ma machine VirtualBox (à CPU unique) (fonctionnant sur un CPU i7-6600U). La machine virtuelle a 3,5 Go de RAM. Selon le Gestionnaire des tâches, 40% + est gratuit et l'activité du disque est de 0% (je suppose que cela signifie aucun échange). L'ajout d'un autre processeur à la machine virtuelle (et l'activation de l'hyper-threading pour les machines physiques) accélèrent à nouveau l'application. Je me demandais simplement, était-ce un compromis intentionnel lors du développement du JDK pour réduire les performances sur les machines à processeur unique (rares) pour rendre la JVM plus rapide sur les processeurs multicœurs / hyper-threading?

java hang java-14 palacsint
la source
3
-Xlog:all=debugN'activer la journalisation GC? Ce serait ma première supposition pour toute pause.
kichik
Avez-vous essayé de courir avec un profileur et de comparer les résultats? Je pense que ce serait la chose naturelle à faire.
Axel
1
consultez également les messages du système Windows, essayez une version différente pour jdk 14. Si tout le reste échoue, escalader comme un problème?
Khanna111
1
@ Yan.F: OpenJDK 11 ne sera pas supporté pour toujours, il est temps de préparer les nouvelles versions et les bugs. De plus, il semble qu'un bogue JDK - qui pourrait être corrigé ou non mais pourrait aussi aider les autres. Bref, pour moi c'est surtout de la curiosité. D'un autre côté, j'aimerais maintenant savoir ce que nos clients doivent dire en tant que configuration système minimale requise pour notre application.
palacsint le
1
@ Khanna111: Oui, je viens de l'écrire comme réponse.
palacsint Il y a

Réponses:

6

D'après mon expérience, les problèmes de performances avec les JDK sont principalement liés à l'un des éléments suivants:

  • Compilation JIT
  • Configuration de la machine virtuelle (tailles de tas)
  • Algorithme GC
  • Changements dans la JVM / JDK qui cassent les bonnes applications connues
  • (Oh, et j'ai oublié de mentionner le chargement des cours ...)

Si vous utilisez simplement la configuration JVM par défaut depuis OpenJDK11, vous devriez peut-être définir certaines des options les plus importantes sur des valeurs fixes, comme GC, taille de segment de mémoire, etc.

Peut-être qu'un outil d'analyse graphique pourrait aider à suivre votre problème. Comme Retrace, AppDynamics ou FlightRecorder et similaires. Celles-ci donnent plus de vue d'ensemble sur l'état général du tas, des cycles gc, de la RAM, des threads, de la charge CPU et ainsi de suite à un moment donné que les fichiers journaux ne pouvaient fournir.

Dois-je bien comprendre que votre application écrit environ 30710 lignes dans le journal dans la première seconde de l'exécution (sous OpenJDK11)? Pourquoi écrit-il "seulement" environ 7k lignes sous OpenJDK14 dans la première seconde? Cela semble être une énorme différence pour une application qui vient de démarrer sur différentes machines virtuelles Java pour moi ... Êtes-vous sûr qu'il n'y a pas par exemple de grandes quantités de traces de pile d'exceptions déversées dans le journal?
Les autres chiffres sont parfois encore plus élevés, alors peut-être que les ralentissements sont liés à la journalisation des exceptions? Ou même l'échange, si la RAM devient faible?
En fait, je pense que si une application n'écrit rien dans le journal, c'est un signe de bon fonctionnement sans problème (sauf si elle est complètement gelée dans ce temps). Que se passe-t-il entre les secondes 12 et 22 (dans le cas d'OpenJDK14 ici) est ce qui m'inquiète le plus ... les lignes enregistrées passent par le toit ... pourquoi ?
Et après, la journalisation descend à des valeurs basses de tous les temps d'environ 1-2k lignes ... quelle est la raison de cela ?? (eh bien, c'est peut-être le gc qui intervient au deuxième 22 et une tabula rasa qui résout certaines choses ...?)

Une autre chose peut être votre déclaration sur les machines "à processeur unique". Cela implique-t-il également un «noyau unique» (Idk, peut-être que votre logiciel est conçu sur du matériel hérité ou quelque chose)? Et les machines virtuelles "à processeur unique" fonctionnent sur ces machines? Mais je suppose que je me trompe sur ces hypothèses, car presque tous les processeurs sont multicœurs de nos jours ... mais j'examinerais peut-être un problème de multithreading (blocage).

Antares
la source
2
Veuillez ne pas utiliser de signatures ou de slogans dans vos messages, le "GL et HF" répétitif est considéré comme du bruit et une distraction du contenu de votre message ici. Voir meta.stackexchange.com/help/behavior pour plus d'informations.
meagar
1
"Est-ce que je comprends bien que votre application écrit environ 30710 lignes dans le journal dans la première seconde d'exécution (sous OpenJDK11)?" - Oui tu as raison.
palacsint
1
"Etes-vous sûr qu'il n'y a pas, par exemple, de grandes quantités de traces de pile d'exceptions déversées dans le journal?" - Le journal est propre, je n'y ai rien trouvé d'étrange, l'application fonctionne correctement (sauf qu'elle s'exécute très-très lentement).
palacsint le
1
GC donne un coup de pied dans la 22e seconde et l'application reste lente après cela. J'ai également mis à jour la question. Veuillez noter que l'application de démonstration update4j a également le même problème. Merci pour la réponse!
palacsint
1
30k + lignes de log en une seconde est assez énorme ... vous n'êtes pas d'accord? Je me demande vraiment ce qui pourrait être utile d'être connecté pour accepter ce nombre élevé de lignes de journal en si peu de temps ... Avez-vous essayé de désactiver complètement la journalisation et de profiler l'application dans ce mode? (Je suis curieux, mais peut-être que la journalisation n'a vraiment aucun impact comme vous l'imaginez avec le comportement update4j)
Antares
5

Comme il utilise 100% de CPU "la plupart du temps" et que cela prend 10 fois plus de temps (!) Avec Java 14, cela signifie que vous gaspillez 90% de votre CPU en Java 14.

Le fait de manquer d'espace de stockage peut le faire, car vous passez beaucoup de temps dans GC, mais vous semblez l'avoir exclu.

Je remarque que vous ajustez l'option de verrouillage biaisé et que cela fait une différence significative. Cela me dit que votre programme fait peut-être beaucoup de travail simultané dans plusieurs threads. Il est possible que votre programme ait un bogue de concurrence qui s'affiche en Java 14, mais pas en Java 10. Cela pourrait également expliquer pourquoi l'ajout d'un autre processeur le rend plus de deux fois plus rapide.

Les bogues de concurrence n'apparaissent souvent que lorsque vous n'avez pas de chance, et le déclencheur aurait pu être quelque chose, comme un changement dans l'organisation de la table de hachage, etc.

Tout d'abord, si cela est possible, recherchez les boucles qui pourraient être occupées à attendre au lieu de dormir.

Ensuite, exécutez un profileur en mode d'échantillonnage (jvisualvm fera l'affaire) et recherchez des méthodes qui prennent beaucoup plus de temps total qu'elles ne le devraient. Étant donné que vos performances sont diminuées d'un facteur 10, tout problème devrait vraiment sauter.

Matt Timmermans
la source
Le verrouillage biaisé était nécessaire dans le passé, mais de nos jours pas tellement, et il est proposé de le désactiver par défaut et de le supprimer plus tard: openjdk.java.net/jeps/374
JohannesB il y a
3

TL; DR : C'est une régression OpenJDK.

Je n'ai pas excepté cela, mais j'ai pu reproduire le problème avec un simple bonjour:

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

J'ai utilisé ces deux fichiers batch:

main-1cpu.bat, ce qui limite le javaprocessus à un seul processeur:

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, le javaprocessus peut utiliser les deux CPU:

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

(Les différences sont la affinityvaleur et le nom du fichier journal. Je l'ai encapsulé pour une lecture plus facile mais l'habillage avec \ne fonctionne probablement pas sous Windows.)

Quelques mesures sur Windows 10 x64 dans VirtualBox (avec deux CPU):

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
...

Les tracelogs produits contiennent des pauses similaires que vous pouvez voir dans la question.

L'exécution Mainsans tracelogs est plus rapide mais la différence est toujours visible entre la version à un seul processeur et la version à deux processeurs: ~ 4-7 secondes contre ~ 400 ms.

J'ai envoyé ces résultats à la liste de diffusion hotspot-dev @ openjdk et les développeurs y ont confirmé que c'est quelque chose que le JDK pourrait mieux gérer . Vous pouvez également trouver des correctifs supposés dans le fil. Espérons que cela sera corrigé dans OpenJDK 15.

palacsint
la source
2

Il s'agit d'un problème intéressant qui nécessiterait des efforts indéterminés pour le réduire, car de nombreuses permutations et combinaisons doivent être testées et les données collectées et rassemblées.

Il semble qu'il n'y ait pas eu de résolution à ce problème depuis un certain temps. Peut-être faudrait-il intensifier cela.

EDIT 2: Étant donné que "ThreadLocalHandshakes" est obsolète et que nous pouvons supposer que le verrouillage est contesté, suggérez d'essayer sans "UseBiasedLocking" pour accélérer, espérons-le, ce scénario.

Cependant, il existe quelques suggestions pour collecter plus de données et tenter d'isoler le problème.

  1. Allouez plus d'un noyau [Je constate que vous l'avez essayé et le problème disparaît. Semble être un problème avec une exécution de thread / s excluant les autres. Voir n ° 7 ci-dessous)
  2. Allouer plus de tas (peut-être que les exigences de la v14 sont plus importantes que celles des jdks précédents)
  3. Allouez plus de mémoire au Win 10 VB.
  4. Vérifiez les messages du système d'exploitation (Win 10 dans votre cas)
  5. Exécutez-le dans un Win 10 non virtualisé.
  6. Essayez une version différente de JDK 14
  7. Faites un vidage de thread tous les (ou profils) quelques intervalles de temps. Analysez quel thread s'exécute exclusivement. Il existe peut-être un cadre pour un partage équitable du temps. Il y a peut-être un thread de priorité supérieure en cours d'exécution. Quel est ce fil et que fait-il? Sous linux, vous pouvez statuer en temps réel les processus légers (threads) associés à un processus et son état. Quelque chose de similaire sur Win 10?
  8. L'utilisation du processeur? 100% ou moins? Contraint par CPU ou mem? 100% CPU dans les threads de service? Quel fil de service?
  9. Avez-vous explicitement défini un algo GC?

J'ai personnellement été témoin de problèmes dans les versions qui ont à voir avec GC, redimensionnement de tas, problèmes avec les conteneurs virtualisés et ainsi de suite.

Il n'y a pas de réponse facile à cela, je pense, d'autant plus que cette question existe depuis un certain temps. Mais nous pouvons essayer, tout le meilleur et nous faire savoir quel est le résultat de certaines de ces étapes d'isolement.

EDIT 1: à partir de la question mise à jour, il semble être lié à un GC ou à un autre thread de service prenant en charge le noyau unique de manière non équitable (Thread-Local Handshakes)?

Khanna111
la source
L'ajout d'un cœur de processeur supplémentaire utilisé pour déclencher le passage de l'ergonomie Java sur des systèmes 32 bits d'un client à un serveur de classe vm avec un GC différent et une compilation à plusieurs niveaux, si cela est toujours le cas, cela peut expliquer des différences soudaines dans les performances et l'utilisation de la mémoire, oui JVM la performance est compliquée
Johannes
3
L'ergonomie Java (paramètres par défaut) reste différente pour 1 CPU (ex: -XX: + UseSerialGC) ou 2 CPU (ex: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Mais après avoir vérifié avec -XX: + PrintFlagsFinal que j'ai ajusté tous les paramètres au même update4j en cours d'exécution ou similaire était encore extrêmement lent à démarrer avec un seul au lieu de 2 CPU avec cmd.exe / C start / affinity 0x1 (mais extrêmement rapide avec 0x3 - utilisant ainsi 2 cpus (1 + 10 binaire)). J'ai confirmé que nous ne pouvons blâmer aucun garbage collector en utilisant Epsilon GC qui est conçu pour éviter toute surcharge du GC. La compilation à plusieurs niveaux est cependant activée
JohannesB
Je vois. Avec Epsilon GC, il semble que ce fut aussi lent. Dans ce cas, les statuts de threads et les vidages pour évaluer où il est bloqué pourraient être un moyen. À la fois dans le monde Java et le monde OS (Linux si je me souviens était gcore)
Khanna111
1

Soyez prudent avec la journalisation pour ralentir les disques, cela ralentira votre application:

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

Mais cela ne semble pas être la cause du problème car le CPU est toujours occupé et vous n'avez pas à attendre que tous les threads arrivent à un point sûr grâce à la négociation locale du thread: https: // openjdk. java.net/jeps/312

De plus, pas directement lié au problème que vous rencontrez, mais plus généralement si vous voulez essayer d'extraire plus de performances de votre matériel pour le temps de démarrage, jetez un œil à AppCDS (partage de données de classe):

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

JohannesB
la source