May 29, 2021

all posts ->

Parfois votre application fonctionne, mais vous voulez ameliorer les performances en augmentant son debit ou en reduisant la latence. D’autres fois, vous voulez simplement savoir comment le code se comporte a l’execution, determiner ou se trouvent les points chauds, ou comprendre comment un framework fonctionne sous le capot.

C’est un cas d’utilisation parfait pour les profileurs. Ils offrent une vue d’ensemble de portions d’execution arbitrairement grandes, ce qui vous aide a voir les problemes a grande echelle.

Beaucoup de gens pensent qu’ils n’ont pas besoin d’apprendre a profiler tant qu’ils n’ecrivent pas d’applications a forte charge. Dans l’exemple, nous verrons comment nous pouvons beneficier du profilage meme avec des applications tres simples.

Application exemple

Disons que nous avons le programme suivant :

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

Le programme essaie de creer un chemin dans le systeme de fichiers de maniere repetee en utilisant createDirectories() de NIO2. Ensuite, nous mesurons le debit a l’aide d’un benchmark improvise.

Chaque fois qu’une tache s’execute, la logique du benchmark stocke l’horodatage actuel dans une collection et supprime tous les horodatages qui pointent vers un moment anterieur au moment actuel moins un certain intervalle. Cela permet de savoir combien d’evenements se sont produits pendant cet intervalle de temps en interrogeant simplement la collection. Ce benchmark est cense nous aider a evaluer les performances de la methode createDirectories() .

Lorsque nous executons le programme, nous constatons que les chiffres sont etonnamment bas :

Average count: 6623 op
Spent time: 1462 ms

Profilons-le et voyons ce qui ne va pas.

Obtenir un snapshot

D’abord, nous devons collecter des donnees de profilage, ce qu’on appelle aussi un snapshot. A cette etape, le profileur s’execute aux cotes du programme en collectant des informations sur son activite. Les profileurs utilisent differentes techniques pour y parvenir, comme l’instrumentation des entrees et sorties de methodes. IntelliJ Profiler fait cela en collectant periodiquement les informations de pile de tous les threads executant l’application.

Pour attacher le profileur depuis IntelliJ IDEA, choisissez une configuration d’execution que vous utiliseriez normalement pour executer l’application, et selectionnez Profile dans le menu.

Lorsque l’application a fini de s’executer, une popup apparaitra, nous invitant a ouvrir le snapshot. Si nous fermons la popup par erreur, le snapshot sera toujours disponible dans la fenetre d’outils Profiler.

Ouvrons le rapport et voyons ce qu’il contient.

Analyser le snapshot

La premiere chose que nous voyons apres avoir ouvert le rapport est le graphique de flammes. C’est essentiellement un resume de toutes les piles echantillonnees. Plus le profileur a collecte d’echantillons avec la meme pile, plus cette pile s’elargit sur le graphique de flammes. Ainsi, la largeur du cadre est approximativement equivalente a la part de temps passe dans cet etat.

A notre surprise, la methode createDirectories() n’a pas represente la majorite du temps d’execution. Notre benchmark maison a pris environ le meme temps a s’executer !

De plus, si nous regardons le cadre au-dessus, nous voyons que c’est principalement a cause de la methode removeIf() , qui represente presque tout le temps de son appelant, update() .

Cela merite clairement d’etre examine.

Optimiser le benchmark

Il semble que le code responsable de la suppression des evenements de la file d’attente effectue un travail supplementaire.

Puisque nous utilisons une collection ordonnee, et que les evenements sont ajoutes dans l’ordre chronologique, nous pouvons etre surs que tous les elements a supprimer sont toujours en tete de la file d’attente. Si nous remplacons removeIf() par une boucle qui s’arrete des qu’elle commence a iterer sur des evenements qu’elle ne va pas supprimer, nous pouvons potentiellement ameliorer les performances :

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

Changeons le code, puis profilons a nouveau notre application et regardons le resultat :

La surcharge de la logique du benchmark est maintenant minimale comme elle devrait l’etre, et le cadre createDirectories() occupe maintenant environ 95% de l’ensemble du temps d’execution.

L’amelioration est egalement visible dans la sortie console :

Average count: 14788 op
Spent time: 639 ms

Profilage natif

Ayant resolu le probleme dans le benchmark, nous pourrions nous arreter la et nous feliciter. Mais que se passe-t-il avec notre methode createDirectories() ? Est-elle trop lente ?

Il semble y avoir peu de place pour l’optimisation ici, puisque c’est une methode de bibliotheque, et nous n’avons pas le controle sur son implementation. Pourtant, le profileur peut nous donner un indice.

En developpant les cadres de bibliotheque replies, nous pouvons inspecter ce qui se passe a l’interieur.

Cette partie du graphique de flammes montre que le principal contributeur au temps d’execution de createDirectories() est sun.nio.fs.UnixNativeDispatcher.mkdir0 . Une grande partie de ce cadre n’a rien au-dessus. C’est ce qu’on appelle le temps propre de la methode et indique qu’il n’y a pas de code Java au-dela de ce point. Il pourrait cependant y avoir du code natif.

Puisque nous essayons de creer un repertoire, ce qui necessite d’appeler l’API du systeme d’exploitation, nous pouvons nous attendre a ce que le temps propre de mkdir soit domine par les appels natifs. UnixNativeDispatcher dans le nom de la classe semble le confirmer.

Activons le profilage natif dans Settings | Build, Execution, Deployment | Java Profiler | Collect native calls:

Reexecuter l’application avec le profilage natif active nous montre l’image complete :

Voici le piege. La documentation de la methode createDirectories() dit :

La description est valide du point de vue Java, car elle ne leve aucune exception Java. Cependant, lors de la tentative de creation d’un repertoire qui existe deja, des exceptions sont levees au niveau du systeme d’exploitation. Cela conduit a un gaspillage significatif de ressources dans notre scenario.

Essayons d’eviter cela et enveloppons l’appel a createDirectories() dans une verification Files.exists() :

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

Le programme devient ultra rapide !

Average count: 50000 op
Spent time: 87 ms

Il est maintenant environ 16 fois plus rapide qu’a l’origine. Cette gestion des exceptions etait vraiment couteuse ! Les resultats peuvent differer selon le materiel et l’environnement, mais ils devraient etre impressionnants de toute facon.

Comparaison de snapshots

Si vous utilisez IntelliJ Profiler, il existe un outil pratique qui vous permet de comparer visuellement deux snapshots. Pour une explication detaillee et les etapes, je recommande de consulter la documentation. Voici un bref apercu des resultats que montre la comparaison :

Les cadres absents du snapshot plus recent sont surlignees en vert, tandis que les nouveaux sont colores en rouge. Si un cadre a plusieurs couleurs, cela signifie que le cadre est present dans les deux snapshots, mais que son temps d’execution global a change.

Comme visible dans la capture d’ecran ci-dessus, la grande majorite des operations effectuees a l’origine par notre programme etaient inutiles, et nous avons pu les eliminer. CountEvents.update() est completement vert, ce qui signifie que notre premier changement a abouti a une amelioration quasi complete du temps d’execution de la methode. L’ajout de Files.exists() n’etait pas une amelioration a 100%, mais il a effectivement supprime createDirectories() du snapshot, n’ajoutant que 60 ms au temps d’execution du programme.

Conclusion

Dans ce scenario, nous avons utilise un profileur pour detecter et corriger un probleme de performance. Nous avons egalement ete temoins de la facon dont meme une API bien connue peut avoir des implications qui affectent serieusement les temps d’execution d’un programme Java. Cela nous montre pourquoi le profilage est une competence utile meme si vous n’optimisez pas pour des millions de transactions par seconde.

Dans les prochains articles, nous considererons d’autres cas d’utilisation et techniques de profilage. Restez a l’ecoute !

all posts ->

---

• Créé par Igor Kulakov. Amusez-vous bien !
• Détecteur de doublons

• S'abonner

• 
• 
• 
•