logo le blog invivoo blanc

Ne devinez pas, mesurez avec JProfiler !

6 mai 2021 | Design & Code, Java | 0 comments

Un profiler Java (Jprofiler) est un outil qui analyse les opérations au niveau de la JVM (Java Virtual Machine) pour en déduire des métriques sur la création d’objets, les exécutions itératives, les exécutions de threads et le fonctionnement du ramasse-miettes (Garbage Collector).

Les applications regorgent de fonctionnalités toujours plus variées, et malgré des machines de plus en plus puissantes, les problématiques de performances sont plus que jamais omniprésentes. Il ne suffit pas de faire un code qui répond aux attentes fonctionnelles, il faut également que l’expérience utilisateur soit optimale.

Nous allons dans cet article vous présenter quelques fonctionnalités de JProfiler qui est un incontournable parmi les outils de profiling en environnement Java.

I. Introduction à JProfiler

JProfiler est un outil unique par rapport à ses concurrents, l’outil propose une analyse combinée pour fournir différentes perspectives et les vues sont très intuitives. Il est possible d’utiliser l’outil en local ou de le brancher sur une application distante. Si vous voulez échanger ou en apprendre plus à ce sujet, rapprochez-vous de notre expertise Java à l’initiative de cet article !

JProfiler se branche à la JVM cible en utilisant un agent JProfiler et ainsi il en collecte les données permettant l’analyse. Une interface utilisateur JProfiler permet d’avoir une analyse visuelle de ces données collectées et un utilitaire de ligne de commande fournit une multitude de fonctions.

Le schéma ci-dessous fournit par l’éditeur du logiciel présente en détail les différents composants et interactions entre eux :

L’outil fournit une approche 4 en 1 plus rapide où les 4 vues sont regroupées dans une seule fenêtre :

  • Vue de la mémoire
  • Vue du processeur
  • Vue des threads
  • Des vues de télémétrie VM

Nous avons également des plugins pour la plupart des IDEs (Eclipse, IntelliJ et Netbeans…).

Une fois le logiciel installé ainsi que le plugin pour votre IDE vous avez deux boutons sur votre IDE qui permettent de lancer directement votre projet en mode profilé ou alors de brancher une session de profiling sur une instance de JVM qui tourne déjà :

La page d’accueil vous fait apparaitre sur un aperçu global des métriques de votre projet.

  • Informations sur la mémoire avec en vert la mémoire allouée et en bleu la mémoire utilisée
  • L’activité du ramasse-miettes de la machine virtuelle (GC Activity)
  • Le nombre de classes avec en vert les classes non profilées et en bleu les classes profilées
  • L’activité des threads (en cours, bloqués, en attente…)
  • Et en dernier l’activité du CPU

II. Gestion de la mémoire

Live Memory est une fonctionnalité de JProfiler qui nous permet de voir l’utilisation actuelle de la mémoire par notre application.

Ici nous sommes passés de moins de 100Mo à plus de 700Mo qui n’est jamais redescendue, il y a potentiellement une fuite de mémoire. Nous pouvons alors analyser l’onglet « Live Memory » pour avoir plus de détails sur ce qu’il s’est produit :

On remarque une dominance de deux objets qui monopolisent à eux deux 640mo soit la quasi-totalité de la mémoire allouée de notre application, ici il s’agit d’un objet HashMap ainsi qu’un objet du domaine.

Maintenant que nous avons identifié qu’il y a clairement deux objets qui monopolisent notre mémoire nous pouvons passer à l’analyse des objets via l’onglet « Recorded Objects » :

II. 1. Allocation Call Tree

L’onglet « Allocation Call Tree » peut se traduire par arborescence des allocations de la mémoire. Cet onglet nous permet de partir du point d’entrée de notre application et de déplier petit à petit les différentes méthodes avec à chaque fois un pourcentage d’utilisation de la mémoire pour chacune.

Pour commencer l’enregistrement de la pile d’appel mémoire, il suffit de cliquer sur le bouton « Record Memory » et ensuite d’effectuer les actions qui provoquent la fuite de mémoire :

Une fois les actions effectuées vous pouvez calculer le résultat simplement en cliquant sur le bouton « Calculate » :

Vous aurez alors le résultat de la pile d’appel, sur notre exemple nous identifions clairement la méthode qui nous pose problème à savoir la méthode BookService.populateAuthorMap.

Cette méthode consomme la quasi-totalité de la mémoire, deux appels dans cette méthode sont coûteux, à savoir l’ajout dans un structure de type Map et l’initialisation d’un objet du domaine (la classe Author) :

II. 2. Allocation Hot Spot

Ici c’est la démarche inverse qui est faite, nous partons des différents « Hot Spot » ou points chauds et qui correspondent à la liste des méthodes qui consomment le plus ordonnées par pourcentage d’utilisation de la mémoire.

Il nous est alors possible de déplier chacune de ces méthodes pour identifier la méthode appelante.

Vous pouvez remarquer que nous retrouvons nos deux méthodes identifiées dans le chapitre précédent, à savoir le put sur une structure de type Map et l’initialisation d’un objet métier, toutes les deux appelées par la même méthode #BookService.populateAuthorMap.

Nous allons sauvegarder un « snapshot » qui est en quelque sorte l’export figé de l’état de la mémoire à l’instant T, ce « snapshot » pourra être utilisé par la suite pour les comparaisons des améliorations sur la mémoire de notre application.

Dans notre cas la fuite mémoire était causé par ce service :

private static Map<Author, List<Book>> staticMap = new HashMap<>();

public void populateAuthorMap() {
    for (int i = 0; i < 10_000_000; i++) {
        staticMap.put(new Author("Marouane", "SALIM"), getBooksByAuthorName("Marouane"));
    }
}

La classe utilisée comme clé dans cette Map est la classe Author qui est définie comme suit :

@Getter
@Setter
@Entity
public class Author {

    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private Integer id;
    private String name;
    private String lastName;
    private LocalDate dateOfBirth;
    @OneToMany(cascade = CascadeType.ALL)
    private List<Book> books;

    public Author() {
    }

    public Author(String name, String lastName) {
        this.name = name;
        this.lastName = lastName;
    }
}

Nous avons ici deux problématiques assez triviales dans notre code, la première étant l’utilisation d’un objet statique, en Java, les champs statiques ont une durée de vie qui correspond généralement à la durée de vie entière de l’application, il ne sera alors jamais nettoyé par le ramasse miette.

On aurait tendance également à dire que notre Map utilisée dans la méthode populate aurait qu’un seul enregistrement, car les clés d’une Map sont censées être unique :

    for (int i = 0; i < 10_000_000; i++) {
        staticMap.put(new Author("Marouane", "SALIM"), getBooksByAuthorName("Marouane"));
    }
}

On aurait donc normalement pas eu autant d’instance en mémoire que nous avons identifiés sur la vue des objets en mémoire :

Mais ici le problème est le suivant, les « HashMap » et les « HashSet » utilisent les méthodes « equals() » et « hashCode() » pour identifier si un objet est déjà existant dans la collection. L’implémentation par défaut de ces deux méthodes va uniquement vérifier si c’est la même instance en mémoire et non pas vérifier l’égalité des objets.

Nous allons corriger ces deux anomalies et ainsi pouvoir comparer les métriques, pour cela il suffit d’implémenter les méthodes « hashCode » et « equals » sur l’objet « Author » avec une implémentation qui se base sur les attributs de notre objet.

Une fois la fuite de mémoire corrigée, nous pouvons extraire un nouveau snapshot et faire une comparaison dans une nouvelle fenêtre en utilisant le bouton suivant :

Ensuite nous pouvons sélectionner les deux snapshots et comparer les points chauds, (attention il faut bien choisir l’ordre dans l’ajout des deux snapshots, bien prendre en premier la snapshot d’avant amélioration et en second la snapshot d’après afin d’avoir les résultats corrects) :

Nous remarquons la nette amélioration avec les gains identifiés à -94% pour la classe Author et -100% sur l’utilisation de la structure de données Map.

III. Analyse processeur : CPU Views

L’analyseur de processeur de JProfiler mesure les temps d’exécution des appels de méthode avec leurs piles d’appel. Ces données sont présentées de différentes manières. Selon le problème que vous essayez de résoudre, l’une ou l’autre présentation sera la plus utile. Les données CPU ne sont pas enregistrées par défaut.

Pour commencer l’analyse il vous suffit de cliquer sur le bouton Record CPU :

Une fois votre scénario terminé vous pourrez alors stopper la collecte des données CPU et débuter votre analyse :

III. 1. CPU Call Tree :

L’onglet “Call Tree” est symétrique à l’onglet du même nom de notre chapitre sur la gestion de la mémoire, la seule différence est que les temps et pourcentage affichés correspondent à la durée d’exécution d’une méthode et non pas à la mémoire consommée.

C’est un bon point de départ lorsque nous démarrons le profilage du CPU, JProfiler trie les nœuds fils en fonction de leur temps total, nous pouvons donc ouvrir dans un premier temps la première pile de l’arborescence pour analyser celle qui a le plus d’impact sur les performances.

Prenons l’exemple de la pile d’appel suivante, nous retrouvons une méthode qui consomme la quasi-totalité du temps d’exécution CPU, il s’agit ici de la méthode #BookService.cpuHotSpot.

Si nous détaillons les différents appels issus de cette méthode nous identifions 2 principaux consommateurs, à savoir l’exécution d’une requête (executeQuery) et l’ajout une nouvelle fois dans une structure de type Map.

III. 2. CPU Hot Spot

Une liste de méthodes ordonnées de la plus gourmande en temps d’exécution à la moins gourmande, chaque méthode est dépliable pour afficher la pile d’appel ce qui permet d’analyser les points d’entrées.

Le temps d’exécution est calculé par la somme total des temps d’appels à une méthode, représenté dans la colonne « self time ». Ensuite nous avons les colonnes temps moyen « Average Time » et nombre d’appel à la méthode « Invocations ».

Ici nous identifions de nouveau la principale méthode qui cause des lenteurs #BookService.cpuHotSpot, cette même méthode qui appelle le second point chaud remonté à savoir le executeQuery.

III. 3. Graphique d’appel « Call Graph »

Il est possible d’accéder à une vision graphique des résultats en utilisant l’onglet « Call Graph » et en y sélectionnant les méthodes les plus coûteuses qui sont affichées dans l’ordre décroissant de consommation du processeur :

On y retrouve ici notre méthode en rouge #BookService.cpuHotSpot.

III. 4. Analyse du code et des résultats

Le code de la méthode qui a été identifiée dans le chapitre précédent est le suivant :

public Map<Author, List<Book>> cpuHotSpot(String name, String lastName) {
    Map<Author, List<Book>> booksByAuthor = new HashMap<>();
    for (int i = 0; i < 10_000_000; i++) {
        booksByAuthor.put(new Author(name, lastName),bookRepository.getAllByAuthorName(name));
    }
    return booksByAuthor;
}

Le problème ici est assez trivial, nous avons le même appel qui est exécuté dans une boucle, à savoir bookRepository.getAllByAuthorName(name)); , le résultat de cet appel ne dépend aucunement d’un élément au sein de notre boucle.

Le correctif dans ce cas est de sortir le code qui pose problème à l’extérieur de la boucle, ce qui permettra de l’exécuter une unique fois et non pas autant de fois que d’itération, testons alors le correctif suivant :

public Map<Author, List<Book>> cpuHotSpot(String name, String lastName) {
    Map<Author, List<Book>> booksByAuthor = new HashMap<>();
    List<Book> allByAuthorName = bookRepository.getAllByAuthorName(name);

    for (int i = 0; i < 10_000_000; i++) {
        booksByAuthor.put(new Author(name, lastName), allByAuthorName);
    }
    return booksByAuthor;
}

Que ce soit dans l’analyse de la pile d’appel ou dans l’analyse des points chauds nous avons un résultat significatif sur les performances.

De 480 secondes à 35 secondes sur l’analyse ci-dessous :

Nous pouvons également extraire les « Snapshots » avant/après et effectuer la même procédure que pour la mémoire afin de comparer plus en détail les résultats, nous remarquons de nouveau des gains significatifs, affichés ici en vert :

IV. Threads

Dans le cas du statut des threads de notre application, la vue « Thread History » affiche les chronologies de l’état de tous les threads de la JVM.

Cette vue nous montre chaque thread avec une couleur, la couleur indique l’état du thread.

Les threads sont triés en fonction de leur heure de création et peuvent être filtrés par leurs noms. Une fois les événements enregistrés, vous pouvez survoler les parties d’un thread où il était à l’état en attente « waiting » ou bloqué « blocked » et voir la trace de pile associée.

V. Conclusion

Pour conclure : mesurez, mesurez, mesurez ! Ne pas se fier à nos intuitions sur le code, il faut toujours analyser, comparer à la suite des modifications et utiliser des outils qui permettent d’avoir des métriques fiables.

Il existe d’autres outils open source tels que « Java VisualVM » ou « Yourkit » qui feront l’objet d’un autre article mais JProfiler reste un incontournable en ce qui concerne le profiling en Java.