Profiling efficace en Java avec des outils Open Source

Régulièrement, il arrive que l'on ait à regarder sous le capot d'une application en cours d'exécution. Les raisons en sont diverses: un service particulièrement lent, des plantages, interruptions, blocages et autres pauses fréquentes de JVM, une utilisation de CPU soudaine ou élevée, voire la tant redoutée OutOfMemoryError (OOME). La bonne nouvelle, c'est qu'il existe plusieurs outils permettant d'extraire divers types d'informations d'une JVM en cours d'exécution, permettant d'obtenir ce fameux regard "sous le capot", nécessaire pour diagnostiquer ces situations.

Dans cet article, je vais présenter quelques outils Open Source disponibles à cet effet. Certains de ces outils accompagnent la JVM elle-même, d'autres sont fournis par des tiers. Je débuterai avec l'outil le plus simple de tous, et poursuivrai avec des outils de plus en plus sophistiqués, au fil de l'article. L'objectif principal est de vous permettre d'étoffer votre boîte à outils de diagnostic, ce qui vous rendra bien service lorsque votre application commencera à se comporter bizarrement, ralentira, ou cessera de fonctionner.

Donc, commençons.

Si votre application se met à consommer plus de mémoire qu'habituellement, à se bloquer régulièrement ou à se terminer brutalement avec des OOME, il faut commencer par comprendre quels types d'objets résident en mémoire. Par chance, la JVM permet de le faire très facilement, grâce à l'outil intégré 'jmap'.

Jmap (avec un petit peu d'aide de JPM)

Oracle décrit jmap comme une application qui "affiche des graphes d'objets du modèle mémoire ou le détail du heap, pour un processus donné, un fichier core ou un serveur en débogage distant". Dans cet article, nous allons utiliser jmap pour afficher un histogramme mémoire.

Pour exécuter jmap, vous devez connaître le PID de l'application cible. Une façon simple de l'obtenir est d'utiliser l'outil jps de la JVM, qui listera l'ensemble des processus JVM en cours d'exécution sur la machine, avec leur PID. La sortie écran de jps ressemble à ça:

Figure 1: sortie écran de la commande jps

Pour afficher un histogramme mémoire, nous allons invoquer la console jmap en lui passant le PID de l'application, ainsi que l'option -histo:live. Sans cette option, jmap effectuerait un dump complet du heap de l'application, ce qui n'est pas l'objectif de notre exercice. Donc, si nous souhaitons obtenir un histogramme mémoire de l'application "eureka.Proxy" de la figure précédente, nous invoquons jmap comme suit:

jmap –histo:live 45417

La sortie de la commande ci-dessus ressemble à quelque chose comme ça:

(Cliquez sur l'image pour l'agrandir)

Figure 2: sortie écran de la commande jmap -histo:live, affichant le nombre d'objets dans le heap

Le rapport nous montre une ligne pour chaque type de classe dans le heap, avec le nombre d'instances allouées et le nombre total d'octets consommés.

Pour cet exemple, j'ai demandé à un collègue d'introduire délibérément une fuite mémoire dans l'application. Observez la classe de la ligne 8, CelleData, et comparez sa position dans le rapport suivant, généré juste 4 minutes plus tard.

(Cliquez sur l'image pour l'agrandir)

Figure 3: sortie écran montrant l'augmentation du nombre d'objets pour la classe CelleData

Vous remarquerez que la classe CelleData est désormais la deuxième plus importante dans le système, avec 731.623 instances additionnelles créées dans cet intervalle de 4 minutes. Une heure plus tard, nous observons:

(Cliquez sur l'image pour l'agrandir)

Figure 4: sortie jmap une heure après le démarrage de l'application, montrant plus de 25 millions d'instances de la classe CelleData

Nous avons plus de 25 millions d'instances de la classe CelleData, occupant plus d'un Go de mémoire! Nous avons trouvé notre fuite.

Ce qui est intéressant avec cette donnée, c'est qu'elle est non seulement utile, mais très rapide à obtenir, même pour des heaps de JVM très importants. J'ai pu le tester sur une application active utilisant plus de 17Go de heap, et jmap m'a produit mon histogramme en une minute environ.

Notez que jmap n'est pas un outil de profilage, et que la JVM peut s'interrompre durant la génération du rapport: assurez-vous donc qu'il soit acceptable que votre application puisse être mise en pause pendant toute la durée que prend la génération de l'histogramme. D'après mon expérience toutefois, nous générons surtout des histogrammes lors de l'analyse de bugs sévères, et dans ce genre de circonstances, une petite minute de pause de l'application est généralement acceptable. Et voilà qui me permet de faire la transition en douceur vers notre outil suivant - l'outil de profiling semi-automatique VisualVM.

VisualVM

Un autre outil intégré à la JVM est VisualVM, que ses créateurs décrivent comme "un outil visuel intégrant diverses lignes de commande du JDK et offrant des capacités de profilage légères". En tant que tel, VisualVM est l'un de ces outils que vous êtes susceptibles d'exécuter post-mortem, ou, à tout le moins, après qu'une erreur critique ou un problème de performance ont été identifiés à travers des méthodes plus traditionnelles (une plainte d'utilisateur en étant l'expression la plus courante).

Poursuivons avec notre exemple précédent et son sérieux problème de fuite mémoire. Au bout de 30 minutes d'utilisation, VisualVM nous fournit le graphique suivant:

Figure 5: Graphique de mémoire de VisualVM depuis le démarrage de l'application

Ce graphique montre clairement qu'au bout de 10 minutes d'exécution seulement, vers 19h00, l'application utilise déjà 1Go de heap. Au bout de 23 minutes, la JVM atteint le plafond de son seuil -Xmx3g, ce qui nous donne une application extrêmement lente, un système lent et pléthore d'OOME.

Ayant identifié la cause de ce pic à l'aide de jmap, et après l'avoir corrigée, nous rééxécutons l'application sous la supervision de VisualVM et observons ce qui suit:

Figure 6: Graphique de mémoire de VisualVM après correction de la fuite mémoire

Comme vous pouvez le constater, la courbe de mémoire de l'application (toujours en -Xmx3g) apparaît en bien meilleure santé.

Outre cet outil d'analyse graphique de la mémoire, VisualVM fournit également un sampler et un profiler léger.

Le sampler de VisualVM permet de mesurer périodiquement l'usage du CPU et de la mémoire. Il est possible d'obtenir des statistiques similaires à celles de jmap, avec en plus une mesure de l'usage du CPU par méthode. Ceci permet d'obtenir un aperçu rapide des temps d'exécution des méthodes, échantillonné à intervalles réguliers:

(Cliquez sur l'image pour l'agrandir)

Figure 7: tableau temporel de VisualVM pour l'exécution des méthodes

Le profiler de VisualVM vous donnera la même information que le Sampler, mais plutôt qu'une mesure périodique, il permet de collecter des statistiques dans le cadre normal de l'exécution de l'application (grâce à de l'instrumentation du bytecode de la source). Les statistiques obtenues sont plus précises, et mises à jour plus fréquemment, que les données collectées par le Sampler.

(Cliquez sur l'image pour l'agrandir)

Figure 8: sortie écran du Profiler VisualVM

L'utilisation du profiler a quand même un inconvénient: le profiler fonctionne en effet un peu en "force brute". L'instrumentation mise en oeuvre va essentiellement redéfinir la plupart des classes et méthodes de l'application, ce qui ralentira considérablement l'exécution de l'application. Par exemple, l'exécution d'une analyse classique sur l'application présentée ci-dessus a donné un temps total d'exécution d'environ 35 secondes. En activant le Profiler de VisualVM, cette même analyse a pris 31 minutes.

Il faut comprendre que VisualVM n'est pas un Profiler complet, car pas capable de tourner en permanence sur une JVM en production. Ses données ne sont pas sauvegardées, et aucun système de définition/notification d'alertes n'est disponible. Afin de nous rapprocher de notre cible de Profiler complet, étudions maintenant BTrace, un agent Java Open Source complet.

BTrace

Imaginez que vous puissiez indiquer à votre JVM de production exactement quels types d'information vous souhaitez collecter (et par voie de conséquence, quels types d'information ignorer). À quoi cette liste ressemblerait-elle? J'imagine que la réponse à cette question varie en fonction des personnes et des scénarios considérés. Personnellement, j'aime bien avoir les statistiques suivantes:

• L'utilisation mémoire pour le Heap, Non-Heap, Permanent Generation, ainsi que les différents pools mémoires de la JVM (New Generation, Tenured Generation, Survivor Space etc.)
• Le nombre de threads actifs de l'application, avec une catégorisation par type de threads (et leur nombre)
• La charge CPU de la JVM
• Le rapport d'utilisation CPU du système (charge moyenne / disponible)
• Pour certaines classes et méthodes de mon application, je veux voir le nombre d'invocations, le temps moyen d'exécution et le temps moyen de restitution (wall clock time)
• Le nombre d'invocations et les temps d'exécution des appels SQL
• Le nombre d'invocations et les temps d'exécution des opérations disque/réseau

BTrace peut récupérer l'ensemble de ces informations, et permet même de paramétrer exactement ce qu'il faut récupérer, à l'aide de scripts. Ce qui est agréable avec ces scripts, c'est qu'ils s'écrivent sous forme de classes Java classiques, avec des annotations spécifiques indiquant comment BTrace doit instrumenter l'application. Les scripts sont compilés en fichiers .class par le compilateur BTrace - btracec.

Un script BTrace s'organise en plusieurs parties, comme le montre le diagramme ci-dessous. Pour une explication plus complète du script présenté, n'hésitez pas à consulter cette page, ainsi que le site web du projet BTrace.

BTrace n'est qu'un agent, son travail est donc terminé une fois qu'il a sauvegardé ses résultats. BTrace ne propose aucune fonctionnalité de visualisation dynamique autre qu'un simple rapport au format texte. Par défaut, la sortie d'un script BTrace est imprimée dans un fichier texte aux côtés du fichier .class, et s'intitule NomDeVotreScript.class.btrace.

Il est également possible de passer un paramètre supplémentaire à BTrace, afin de lui demander de générer plusieurs fichiers de log, à divers intervalles de temps. Gardez à l'esprit qu'il ne peut y avoir que 100 fichiers au total. Ainsi, une fois le fichier *.class.btrace.99 généré, BTrace écrira le prochain fichier dans *.class.btrace.00, écrasant le fichier existant. Si vous spécifiez un intervalle d'écriture relativement élevé (par exemple 7,5 secondes), cela vous donnera normalement assez de temps pour analyser le rapport. Pour activer cette génération de fichiers multiples, ajoutez le paramètre fileRollMilliseconds=7500 aux paramètres d'entrée de l'agent.

L'un des gros inconvénients de BTrace est son format de reporting, assez primitif et difficile à analyser. Vous en viendrez rapidement à souhaiter une meilleure façon de traiter les données produites par BTrace, par exemple à l'aide d'une interface graphique dynamique. De même, les possibilités de comparer les données dans le temps, ainsi que d'envoyer des alertes lorsque certains seuils prédéfinis sont franchis, vous manqueront peut-être. Et c'est là qu'entre en jeu un autre outil Open Source, EurekaJ.

(Cliquez sur l'image pour l'agrandir)

Figure 9: Parties obligatoires d'un script BTrace pour l'activation du profilage d'une méthode

EurekaJ

J'ai commencé à écrire EurekaJ en 2008. À cette époque, j'avais recherché un outil Open Source avec les fonctionnalités de profilage que j'attendais, mais sans succès, et décidai alors d'écrire le mien. Lors du processus de développement, j'étudiai diverses technologies et modèles architecturaux, qui me permirent d'aboutir à la première livraison d'EurekaJ. Vous pouvez découvrir la genèse d'EurekaJ, lire son code source ou le télécharger à partir du site web du projet.

Pour résumer, EurekaJ fournit deux applications principales:

• Un contrôleur écrit en Java (Manager), qui récupère des statistiques en entrée et fournit une vue permettant de les afficher de façon claire,
• Une application intermédiaire (Proxy BTrace), en charge d'interpréter un output BTrace, de le convertir en JSON et de l'envoyer au contrôleur, par REST.

EurekaJ accepte ainsi deux formats pour les données entrantes. Le proxy EurekaJ lit des données de sortie BTrace converties en fichier CSV (facile à obtenir à partir de BTrace), et le Manager attend des données compatibles avec son interface REST. Vous pouvez donc injecter des données soit à travers le Proxy, soit directement via l'interface REST.

Le Manager EurekaJ vous permet de regrouper des statistiques dans un graphique unique, de définir des seuils d'alerte, et de notifier ces alertes par email. Il est possible de visualiser aussi bien des données en temps réel que des données historiques.

Toutes les données collectées sont organisées en un arbre de données, dont la structure est paramétrée par l'auteur des scripts BTrace. Il est conseillé de regrouper ensemble les statistiques similaires, afin de les rendre plus tard plus accessibles dans EurekaJ. Par exemple, j'ai l'habitude de structurer mes statistiques en groupes logiques, comme suit:

Figure 10: Exemple de groupes de statistiques de l'application de démonstration EurekaJ

Exemples de graphiques

L'une des métriques importantes à collecter est la charge moyenne du système sur lequel réside l'application en cours d'exécution. La cause de la lenteur d'une application peut en effet se situer en dehors de l'application elle-même, c'est-à-dire se dissimuler dans la machine hébergeant l'application. J'ai parfois débogué des applications présentant des lenteurs occasionnelles, où le coupable s'avérait être l'antivirus installé sur la machine. Il s'agit de genres de choses difficiles à établir, si aucune métrique ne vous guide dans l'analyse. Par exemple, imaginez un graphique vous indiquant à la fois la charge moyenne du système, ainsi que la charge imposée au système par votre processus. Vous trouverez ci-dessous un graphique de la charge moyenne, pendant deux heures, d'un serveur virtuel Amazon EC2 sur lequel tourne l'application de démonstration d'EurekaJ (vous pouvez accéder à cette application avec les login/mot de passe 'user').

(Cliquez sur l'image pour l'agrandir)

Figure 11: Graphique EurekaJ affichant la charge moyenne du système

Les deux lignes du graphique positionnent des seuils d'alerte. Si le graphique franchit la première ligne pendant une période de temps minimale, définie dans l'alerte, alors la métrique passe en statut "avertissement". Similairement, lorsque la seconde ligne est dépassée, la métrique passe en statut "critique" ou "erreur". À chaque changement de statut, un email est envoyé aux destinataires enregistrés.

Dans le scénario ci-dessus, il semble qu'un évènement récurrent, arrivant toutes les 20 minutes, provoque un pic de charge dans le graphique. Il faut, en premier lieu, s'assurer que ce pic est bien généré par l'application, et non par autre chose. Nous pouvons le vérifier en mesurant également la charge du processus sur le CPU. EurekaJ nous permet de le visualiser rapidement, une fois les deux métriques correspondantes sélectionnées depuis le menu. Les deux graphiques sont alors affichés, l'un au-dessus de l'autre.

(Cliquez sur l'image pour l'agrandir)

Figure 12: Affichage de plusieurs graphiques en même temps

Dans l'exemple ci-dessus, la corrélation entre l'usage du CPU par le processus et la charge globale du système apparaît clairement significative.

Plusieurs applications requièrent qu'une ou plusieurs personnes soient immédiatement notifiées lorsque les temps de réponse de l'application se dégradent, ou que l'application devient indisponible. Le graphique ci-après illustre une utilisation de Confluence, le logiciel de Wiki d'entreprise de la société Atlassian. Dans cet exemple, l'usage de la mémoire par l'application augmente rapidement, jusqu'au point où l'application ne dispose plus d'assez de mémoire pour fonctionner. Confluence ne parvient alors plus à traiter les requêtes entrantes, et toutes sortes d'erreurs bizarres viennent s'insinuer dans le log.

Vous pourriez vous attendre à ce que l'application lance une OOME dès que la mémoire devient insuffisante, mais la JVM, en réalité, ne lance cette exception que lorsqu'elle constate que le passage du garbage collector s'est ralenti. En conséquence, notre application n'est pas complètement crashée, et ce n'est que deux heures plus tard que Java va reporter une OutOfMemoryError. Même à ce moment-là, notre application est toujours marquée comme "en cours d'exécution" (c.-à-d. le processus JVM correspondant est toujours actif). Pour des raisons évidentes, aucun outil de monitoring de processus ne va marquer notre application comme "down".

(Cliquez sur l'image pour l'agrandir)

Figure 13: Graphique de Heap EurekaJ montrant un scénario possible d'OutOfMemoryError

En se concentrant sur les deux dernières heures d'exécution, le graphique révèle les métriques suivantes.

(Cliquez sur l'image pour l'agrandir)

Figure 14: Zoom du graphique précédent

Avec EurekaJ, il est possible, et même recommandé, de définir des alertes sur la mémoire heap d'une application. Si l'application utilise régulièrement plus de 95% - 98% (en fonction de la taille totale du heap), alors cela indique clairement un problème de mémoire, et vous devrez soit lui allouer plus de heap (utilisant le paramètre -Xmx), soit trouver un moyen de la coder différemment, de façon à minimiser sa consommation. Par ailleurs, la fonction d'alerte en cas de statistique manquante sera incluse dans une future livraison d'EurekaJ.

Le dernier exemple propose un groupe de graphes exposant l'usage de la mémoire pour 4 applications différentes. Ce type de graphe superposé facilite la comparaison de données entre différentes parties de l'application, ou même entre plusieurs applications ou serveurs. Les 4 applications présentées plus bas ont toutes des besoins et usages de mémoire très différents.

Comme le graphe ci-dessous le montre, différentes applications peuvent avoir des courbes de mémoire différentes. Ces courbes dépendent de facteurs divers, comme les frameworks en action, la stratégie de cache mise en oeuvre, le nombre d'utilisateurs, la charge sur l'application, etc. J'ai inclus le graphe ci-dessous afin de bien mettre en évidence l'importance de bien connaître le comportement de son application, à la fois en période de charge normale et en période de pic, ces éléments influençant directement la définition des seuils d'alerte.

(Cliquez sur l'image pour l'agrandir)

Figure 15: Superposition de graphes

Performance et Vigilance - gardez vos points froids bien froids!

La collecte de chaque mesure s'accompagne généralement d'un petit impact sur la performance du système. Certaines métriques peuvent être considérées comme "gratuites" (ou d'un coût négligeable), alors que d'autres peuvent être coûteuses à collecter. Il est donc essentiel de bien comprendre ce que l'on demande à BTrace, afin de minimiser l'impact de la mise en place du profilage sur la performance de l'application. À ce sujet, retenez les trois principes qui suivent:

• Les mesures échantillonnées (c.-à-d. périodiques) peuvent généralement être considérées comme "gratuites". Si vous mesurez votre charge CPU totale, charge CPU du processus, usage de la mémoire et comptage de threads toutes les 5-10 secondes, alors les quelques millisecondes supplémentaires en résultant sont négligeables. À mon avis, vous devriez toujours collecter des statistiques sur ces métriques, car elles ne vous coûtent quasiment rien.
• Les mesures de traitements longs peuvent aussi être considérées comme "gratuites". En règle générale, un coût de 1700-2500 nanosecondes sera ajouté pour chaque méthode profilée. Si vous mesurez les temps d'exécution de requêtes SQL, de trafic réseau, d'accès disque, exécution de servlet, vous trouverez des valeurs allant de 40 millisecondes (accès disque) à 1 seconde (traitement de servlet). Ainsi, ajouter 2500 nanosecondes à chacune de ces méthodes apparaît négligeable.
• Ne jamais ajouter d'opérations de mesure à des méthodes appelées au sein de boucles.

Il faut suivre le précepte suivant: trouver les points chauds (hotspots), en prenant soin de garder les points froids bien froids. Par exemple, jetez un oeil à la classe suivante:

(Cliquez sur l'image pour l'agrandir)

Figure 16: exemple d'un DAO simple, que nous souhaitons profiler

En fonction du temps d'exécution du SQL défini à la ligne 5, la méthode readStatFromDatabase pourrait se révéler un point chaud. Elle deviendrait un point chaud, par exemple, si la requête renvoyait un nombre de lignes conséquent, avec un effet négatif à la fois sur la ligne 13 (trafic réseau entre l'application et la base de données) et sur les lignes 14-16 (le traitement de chaque ligne du ResultSet). La méthode deviendrait également un point chaud (à la ligne 13) si la base de données prend du temps à renvoyer les résultats.

La méthode buildNewStat, en revanche, ne deviendra probablement jamais un point chaud. Chacune de ses invocations sera effectuée en quelques nanosecondes. Mais l'ajout de 2500 nanosecondes de collecte de métriques pour chaque invocation la transformerait certainement en point chaud, à chaque exécution du SQL. En conséquence, nous éviterons de la profiler.

(Cliquez sur l'image pour l'agrandir)

Figure 17: Montrant quelles parties profiler/ignorer

Mise en oeuvre

La mise en place d'un profilage complet avec EurekaJ s'articule autour des composants suivants:

• L'application à monitorer / instrumenter
• BTrace - l'agent Java
• Les scripts BTrace indiquant à BTrace quelles sont les mesures à effectuer
• Un système de fichiers où les fichiers de log de BTrace peuvent être stockés
• Le Proxy EurekaJ pour transférer la sortie BTrace vers le Manager EurekaJ
• Une installation du Manager EurekaJ (soit localement sur le LAN, ou à distance, avec accès via Internet)

(Cliquez sur l'image pour l'agrandir)

Figure 18: Aperçu d'une architecture possible permettant le profilage d'une application avec les outils décrits dans cet article

Des guides complets d'installation pour chacun de ces produits sont disponibles sur le site web EurekaJ.

Conclusion

À travers cet article, nous avons découvert la puissance offerte par quelques outils Open Source, permettant d'un côté des analyses approfondies et ponctuelles sur une JVM en cours d'exécution, et de l'autre une surveillance étendue et constante des déploiements de nos applications de développement / test / production, à l'aide d'outils de profilage.

J'espère que cet article vous aura fait entrevoir les avantages d'une collecte continue de métriques, ainsi que l'opportunité d'être alerté à chaque fois qu'un seuil prédéfini est franchi.

Merci!

Références

1. Documentation jmap
2. Concepts des scripts BTrace
3. Site du projet BTrace
4. Démonstration EurekaJ
5. Site du projet EurekaJ

A propos de l'auteur

Joachim Haagen Skeie travaille en tant Consultant Senior sur les technologies Java et Web, pour Kantega AS, à Oslo, en Norvège. Il s'intéresse particulièrement au profilage d'applications et plus généralement aux logiciels Open Source. Il peut être contacté sur son compte Twitter.