Que fait la machine virtuelle Java toute la journée ? –

Cet article a été initialement publié par Ampère informatique.

J’ai vu un article de blog à propos gprofng, un nouvel outil de profilage GNU. L’exemple de ce blog était un programme de multiplication matricielle-vecteur écrit en C. Je suis un programmeur Java™ et le profilage d’applications Java est une tâche difficile. souvent difficile avec des outils conçus pour les programmes C compilés statiquement, plutôt que pour les programmes Java compilés au moment de l’exécution. Dans ce blog, je montre que gprofng est facile à utiliser et utile pour approfondir le comportement dynamique d’une application Java.

La première étape consistait à rédiger un programme de multiplication matricielle. J’ai écrit un programme matrice-temps-matrice complet car ce n’est pas plus difficile que matrice-temps-vecteur. Il existe trois méthodes principales : une méthode pour calculer l’addition multipliée la plus interne, une méthode pour combiner les additions multipliées en un seul élément du résultat et une méthode pour itérer le calcul de chaque élément du résultat.

J’ai enveloppé le calcul dans un harnais simple pour calculer le produit matriciel à plusieurs reprises, afin de m’assurer que les temps sont reproductibles. (Voir la note de fin 1.) Le programme affiche le moment où chaque multiplication matricielle démarre (par rapport au démarrage de la machine virtuelle Java) et la durée de chaque multiplication matricielle. Ici, j’ai exécuté le test pour multiplier deux matrices 8000×8000. Le harnais répète le calcul 11 ​​fois, et pour mieux mettre en évidence le comportement plus tard, dort pendant 920 millisecondes entre les répétitions :

$ numactl --cpunodebind=0 --membind=0 -- \
java -XX:+UseParallelGC -Xms31g -Xmx31g -Xlog:gc -XX:-UsePerfData \
  MxV -m 8000 -n 8000 -r 11 -s 920

Figure 1 : Exécution du programme de multiplication matricielle

Notez que la deuxième répétition prend 92 % du temps de la première répétition et que la dernière répétition ne prend que 89 % du temps de la première répétition. Ces variations dans les temps d’exécution confirment que les programmes Java ont besoin d’un certain temps pour s’échauffer.

La question est : puis-je utiliser gprofng pour voir ce qui se passe entre la première répétition et la dernière répétition qui améliore la performance ?

Une façon de répondre à cette question est d’exécuter le programme et de laisser gprofng recueillir des informations sur la course. Heureusement, c’est simple : je préfixe simplement la ligne de commande avec un gprofng commande pour collecter quoi gprofng appelle une « expérience » :

$ numactl --cpunodebind=0 --membind=0 -- \
gprofng collect app \
    java -XX:+UseParallelGC -Xms31g -Xmx31g -Xlog:gc --XX:-UsePerfData \
        MxV -m 8000 -n 8000 -r 11 -s 920

Figure 2 : Exécution du programme de multiplication matricielle sous gprofng

La première chose à noter, comme pour tout outil de profilage, est la surcharge que la collecte d’informations de profilage impose à l’application. Par rapport à l’exécution précédente non profilée, gprofng ne semble imposer aucune surcharge notable.

Je peux alors demander gprofng comment le temps a été passé dans l’ensemble de l’application. (Voir la note de fin 2.) Pendant toute la course, gprofng dit que les 24 méthodes les plus populaires sont :

$ gprofng display text test.1.er -viewmode expert -limit 24 -functions

Figure 3 : affichage Gprofng des 24 méthodes les plus populaires

La vue des fonctions présentée ci-dessus donne les temps CPU exclusifs et inclusifs pour chaque méthode, à la fois en secondes et en pourcentage du temps CPU total. La fonction nommée est une pseudo-fonction générée par gprofng et a la valeur totale des différentes métriques. Dans ce cas, je vois que le temps CPU total consacré à l’ensemble de l’application est de 1,201 seconde.

Les méthodes de l’application (les méthodes de la classe MxV) sont là, occupant la grande majorité du temps CPU, mais il existe d’autres méthodes, y compris le compilateur d’exécution de la JVM (Compilation::Compilation), et d’autres fonctions qui ne font pas partie du multiplicateur matriciel. Cet affichage de l’ensemble de l’exécution du programme capture l’allocation (MxV.allocate) et l’initialisation (MxV.initialize), qui m’intéressent moins puisqu’ils font partie du faisceau de tests, ne sont utilisés qu’au démarrage, et n’ont pas grand chose à voir avec la multiplication matricielle.

je peux utiliser gprofng pour me concentrer sur les parties de l’application qui m’intéressent. L’une des merveilleuses fonctionnalités de gprofng est qu’après avoir rassemblé une expérience, je peux appliquer des filtres aux données collectées. Par exemple, pour observer ce qui s’est passé pendant un intervalle de temps particulier ou pendant qu’une méthode particulière se trouve sur la pile d’appels. À des fins de démonstration et pour faciliter le filtrage, j’ai ajouté des appels stratégiques à Thread.sleep(ms) afin qu’il soit plus facile d’écrire des filtres basés sur des phases de programme séparées par des intervalles d’une seconde. C’est pourquoi le résultat du programme ci-dessus dans la figure 1 a chaque répétition séparée d’environ une seconde, même si chaque multiple matriciel ne prend qu’environ 0,1 seconde.

gprofng est scriptable, j’ai donc écrit un script pour extraire des secondes individuelles du gprofng expérience. La première seconde concerne le démarrage de la machine virtuelle Java.

Figure 4 : Filtrage des méthodes les plus chaudes dans la première seconde. La multiplication matricielle a été artificiellement retardée pendant cette seconde pour me permettre de montrer à la JVM le démarrage

Je peux voir que le compilateur d’exécution démarre (par exemple, Compilation::compile_java_method, occupant 16% du temps CPU), même si aucune des méthodes de l’application n’a commencé à s’exécuter. (Les appels de multiplication matricielle sont retardés par les appels de veille que j’ai insérés.)

Après la première seconde, il y a une seconde pendant laquelle les méthodes d’allocation et d’initialisation s’exécutent, ainsi que diverses méthodes JVM, mais aucun code de multiplication matricielle n’a encore démarré.

Figure 5 : Les méthodes les plus chaudes dans la seconde seconde. L’allocation et l’initialisation de la matrice sont en concurrence avec le démarrage de la JVM

Maintenant que le démarrage de la JVM ainsi que l’allocation et l’initialisation des tableaux sont terminés, la troisième seconde a la première répétition du code de multiplication matricielle, illustré à la figure 6. Mais notez que le code de multiplication matricielle est en concurrence pour les ressources machine avec le compilateur d’exécution Java. (par exemple, CompileBroker::invoke_compiler_on_method8% dans la figure 6), qui compile des méthodes car le code de multiplication matricielle s’avère chaud.

Même ainsi, le code de multiplication matricielle (par exemple, le temps « inclus » dans le MxV.main méthode, 91 %) obtient la majeure partie du temps CPU. Le temps inclusif dit qu’une matrice se multiplie (par exemple, MxV.multiply) prend 0,100 seconde CPU, ce qui correspond au temps de mur signalé par l’application dans la figure 2. (La collecte et le rapport du temps de mur prennent du temps de mur, qui est en dehors du temps CPU gprofng comptes à MxV.multiply.)

Figure 6 : Les méthodes les plus populaires dans la troisième seconde, montrant que le compilateur d’exécution est en concurrence avec les méthodes de multiplication matricielle

Dans cet exemple particulier, la multiplication matricielle n’est pas vraiment en compétition pour le temps CPU, car le test s’exécute sur un système multiprocesseur avec de nombreux cycles d’inactivité et le compilateur d’exécution s’exécute en tant que threads séparés. Dans des circonstances plus restreintes, par exemple sur une machine partagée très chargée, ces 8 % du temps passé dans le compilateur d’exécution peuvent poser problème. D’un autre côté, le temps passé dans le compilateur d’exécution produit des implémentations plus efficaces des méthodes, donc si je calculais de nombreuses multiplications matricielles, c’est un investissement que je suis prêt à faire.

À la cinquième seconde, le code de multiplication matricielle possède la machine virtuelle Java pour elle-même.

Figure 7 : Toutes les méthodes exécutées pendant la cinquième seconde, montrant que seules les méthodes de multiplication matricielle sont actives

Notez la répartition 60 %/30 %/10 % en secondes CPU exclusives entre MxV.oneCell, MxV.multiplyAddet MxV.multiply. Le MxV.multiplyAdd La méthode calcule simplement une multiplication et une addition : mais c’est la méthode la plus interne de la multiplication matricielle. MxV.oneCell a une boucle qui appelle MxV.multiplyAdd. Je peux voir que la surcharge de boucle et l’appel (évaluation des conditions et transferts de contrôle) représentent relativement plus de travail que l’arithmétique simple dans MxV.multiplyAdd. (Cette différence se reflète dans le temps exclusif pour MxV.oneCell à 0,060 seconde CPU, contre 0,030 seconde CPU pour MxV.multiplyAdd.) La boucle externe dans MxV.multiply s’exécute suffisamment rarement pour que le compilateur d’exécution ne l’ait pas encore compilée, mais cette méthode utilise 0,010 seconde CPU.

Les multiplications matricielles se poursuivent jusqu’à la neuvième seconde, lorsque le compilateur d’exécution JVM se déclenche à nouveau, après avoir découvert que MxV.multiply est devenu chaud.

Lors de la répétition finale, le code de multiplication matricielle utilise pleinement la machine virtuelle Java.

Figure 9 : La répétition finale du programme de multiplication matricielle, montrant la configuration finale du code

Conclusion

J’ai montré à quel point il est facile d’avoir un aperçu du temps d’exécution des applications Java en créant un profil avec gprofng. Utilisation de la fonction de filtrage de gprofng examiner une expérience par tranches de temps m’a permis d’examiner uniquement les phases du programme qui m’intéressaient. Par exemple, exclure les phases d’allocation et d’initialisation de l’application, et afficher une seule répétition du programme pendant que le compilateur d’exécution opère sa magie, ce qui m’a permis de mettre en évidence l’amélioration des performances au fur et à mesure de la compilation du hot code.

Lectures complémentaires

Pour les lecteurs qui souhaitent en savoir plus gprofngil y a ce billet de blog avec une vidéo d’introduction sur gprofngy compris des instructions sur la façon de l’installer sur Oracle Linux.

Remerciements

Merci à Ruud van der Pas, Kurt Goebel et Vladimir Mezentsev pour leurs suggestions et leur soutien technique, ainsi qu’à Elena Zannoni, David Banman, Craig Hardy et Dave Neary pour m’avoir encouragé à écrire ce blog.

Notes de fin

1. Les motivations des composants de la ligne de commande du programme sont :

• numactl --cpunodebind=0 --membind=0 --. Limitez la mémoire utilisée par la machine virtuelle Java aux cœurs et à la mémoire d’un nœud NUMA. Restreindre la JVM à un seul nœud réduit la variation d’une exécution à l’autre du programme.
• java. J’utilise la version OpenJDK de jdk-17.0.4.1 pour aarch64.
• -XX:+UseParallelGC. Activez le garbage collector parallèle, car il effectue le moins de travail en arrière-plan parmi les collecteurs disponibles.
• -Xms31g -Xmx31g. Fournissez suffisamment d’espace de tas d’objets Java pour ne jamais avoir besoin d’un garbage collection.
• -Xlog:gc. Enregistrez l’activité du GC pour vérifier qu’une collection n’est effectivement pas nécessaire. (« Faites confiance mais vérifiez. »)
• -XX: -UsePerfData. Réduisez la surcharge de la machine virtuelle Java.

2. Les explications du gprofng les options sont :

• -limit 24. Afficher uniquement les 24 principales méthodes (ici triées par temps CPU exclusif). Je constate que l’affichage de 24 méthodes me permet d’accéder aux méthodes qui ne prennent presque pas de temps. Plus tard, j’utiliserai la limite 16 dans les endroits où 16 méthodes se résument aux méthodes qui contribuent de manière insignifiante au temps CPU. Dans certains des exemples, gprofng lui-même limite l’affichage, car il n’y a pas beaucoup de méthodes qui accumulent du temps.
• -viewmode expert. Affichez toutes les méthodes qui accumulent du temps CPU, pas seulement les méthodes Java, y compris les méthodes natives de la JVM elle-même. L’utilisation de cet indicateur me permet de voir les méthodes du compilateur d’exécution, etc.