Profiler la JVM avec async-profiler

La plupart des profilers Java historiques (VisualVM, les vieux modes par échantillonnage de JProfiler, l’ancien agent hprof) ne capturent les stacks qu’aux safepoints. Le souci, c’est que les threads ne sont pas répartis uniformément dans le code au moment où ils atteignent un safepoint. Certaines méthodes en contiennent beaucoup, d’autres aucune. Le profil obtenu est donc biaisé, et on finit parfois par optimiser du code qui n’est pas le vrai coupable. C’est ce qu’on appelle le safepoint bias.

async-profiler ne souffre pas de ce problème. Il s’appuie sur les perf_events du noyau (ou sur un timer interne) pour interrompre les threads à n’importe quel endroit, puis récupère la stack via AsyncGetCallTrace. Son overhead reste de l’ordre de quelques pour-cent, ce qui le rend utilisable directement en production.

Cet article le prend en main sur un cas concret : une petite application avec trois problèmes plantés exprès, profilée en mode CPU, wall-clock, allocations et locks, puis corrigée et profilée à nouveau. Tout ce qui suit a été exécuté avec async-profiler 4.5 et un JDK 25, dans un conteneur Linux.

Installer l’outil

async-profiler se télécharge depuis la page de releases du projet, sous forme d’archive par plateforme (Linux x64, Linux arm64, macOS). Rien à installer :

curl -sLO https://github.com/async-profiler/async-profiler/releases/download/v4.5/async-profiler-4.5-linux-x64.tar.gz
tar xzf async-profiler-4.5-linux-x64.tar.gz
async-profiler-4.5-linux-x64/bin/asprof --version

L’archive contient deux binaires dans bin/, asprof et jfrconv, et la bibliothèque lib/libasyncProfiler.so. C’est cette bibliothèque qui est chargée dans la JVM cible. asprof ne fait que s’y attacher et lui envoyer des commandes.

Démarrer en une commande

Pour profiler le CPU d’un process déjà lancé pendant 30 secondes et en sortir un flamegraph :

asprof -d 30 -f profile.html <pid>

L’événement par défaut est cpu. Le format de sortie est déduit de l’extension du fichier : un .html donne un flamegraph interactif. À la place du pid, on peut donner le nom de la classe principale tel que jps l’affiche, ou le mot jps s’il n’y a qu’une JVM sur la machine. Pour un premier diagnostic, ça suffit.

L’application de l’exemple

Pour que les profils qui suivent veuillent dire quelque chose, il faut une application avec de vrais défauts. En voici une, courte. Quatre threads worker traitent des commandes en boucle. Pour chaque commande : valider une centaine d’adresses e-mail, construire un rapport texte, puis l’enregistrer dans une base de données simulée par un Thread.sleep(1).

public class Shop {

    static final Object DB = new Object();

    // Problème 1 : la regex est compilée à chaque appel.
    static boolean validate(Order order) {
        for (String email : order.emails()) {
            Pattern p = Pattern.compile("^[\\w.+-]+@[\\w-]+\\.[\\w.]+$");
            if (!p.matcher(email).matches()) return false;
        }
        return true;
    }

    // Problème 2 : le rapport est construit par concaténation dans une boucle.
    static String report(Order order) {
        String out = "";
        for (int i = 0; i < order.lines(); i++) {
            out += "line " + i + ";";
        }
        return out;
    }

    // Problème 3 : l'appel à la base se fait sous un verrou global.
    static void save(Order order, String report) {
        synchronized (DB) {
            fakeDbCall(report);
        }
    }
}

Le thread principal affiche le débit toutes les cinq secondes. Avant toute correction :

708 commandes/s
709 commandes/s
716 commandes/s

On lance la JVM avec les deux flags dont on reparle plus bas, puis on profile.

java -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints Shop 4

Choisir ce qu’on mesure

Le vrai intérêt de l’outil, c’est qu’on couvre plusieurs dimensions avec le même binaire via -e :

asprof -d 15 -e cpu   -f cpu.html   Shop   # temps CPU
asprof -d 15 -e wall  -f wall.html  Shop   # wall-clock (temps réel)
asprof -d 15 -e alloc -f alloc.html Shop   # allocations sur la heap
asprof -d 15 -e lock  -f lock.html  Shop   # contention sur les locks

Voici ce que chacun donne sur notre application.

CPU : où le processeur travaille

Flamegraph CPU de l'application Shop : Shop.work occupe toute la largeur, avec trois blocs au-dessus, validate, save et report

Profil CPU, quinze secondes. Trois blocs au-dessus de Shop.work : report, save et validate.

Le graphe se lit de bas en haut, et l’article sur les flamegraphs détaille la lecture. L’essentiel : Shop.validate prend 49 % du CPU, et presque tout est dans Pattern.compile (36 %), pas dans la vérification elle-même. Shop.report prend 21 %, dans la concaténation de chaînes. Shop.save prend 18 %, et c’est surtout de la mécanique de verrou de la JVM, en jaune.

Le même profil en texte, avec -o flat, donne les méthodes qui étaient au sommet de la pile au moment de l’échantillon :

--- Execution profile ---
Total samples       : 188

          ns  percent  samples  top
  ----------  -------  -------  ---
   160000000    8.51%       16  /usr/lib/aarch64-linux-gnu/libc.so.6
   150000000    7.98%       15  copy_byte_f
   120000000    6.38%       12  java.util.regex.Pattern.has
   110000000    5.85%       11  pthread_cond_signal
   110000000    5.85%       11  java.util.regex.Pattern.clazz
   100000000    5.32%       10  java.util.regex.Pattern.sequence
    80000000    4.26%        8  java.util.regex.Pattern.compile

Ce format répond à « quelle méthode brûle du CPU directement ». Il ne dit pas qui l’appelle. Pour ça, -o traces imprime les piles complètes, les plus fréquentes d’abord :

--- 240000000 ns (12.83%), 24 samples
  [ 0] copy_byte_f
  [ 1] jbyte_disjoint_arraycopy
  [ 2] java.lang.String.getBytes
  [ 3] java.lang.StringConcatHelper.prepend
  [ 4] java.lang.String$$StringConcat.0x00001c0001040c00.prepend
  [ 5] java.lang.String$$StringConcat.0x00001c0001040c00.concat
  ...
  [ 9] Shop.report
  [10] Shop.work

Une copie mémoire native, appelée par la concaténation de chaînes, appelée par report. Le diagnostic est déjà là.

Un détail à connaître : 188 échantillons en quinze secondes, c’est peu. Par défaut, un échantillon CPU est pris toutes les 10 ms de temps processeur consommé. L’application n’utilisait qu’une petite fraction d’un cœur, parce que les workers passent leur temps à attendre. Ce qui nous amène au mode suivant.

Wall-clock : où le temps passe

Le mode cpu ne compte que le temps pendant lequel les threads tournent effectivement sur un cœur. Un thread bloqué sur une I/O, en attente d’un lock ou dans un sleep, il ne le voit pas. Si votre latence vient d’un appel réseau ou d’une requête SQL lente, le profil CPU sera quasiment vide alors que le problème, lui, est bien là. Dans ce cas il faut regarder wall.

En wall-clock, chaque thread reçoit un échantillon à intervalle fixe, qu’il travaille ou qu’il dorme. On l’utilise presque toujours avec -t, qui sépare les piles par thread, et avec un filtre -I pour ne garder que les threads qui nous intéressent. Sans ça, les threads de service de la JVM, qui dorment en permanence, noient le graphe.

asprof -d 15 -e wall -t -I '*worker*' -f wall.html Shop

Flamegraph wall-clock des quatre workers : chaque colonne est dominée par ObjectMonitor::enter sous Shop.save

Wall-clock, quatre workers. Presque toute la largeur est sous Shop.save.

Le résultat est clair. Chaque worker passe 97 % de son temps dans Shop.save. Sur ce temps, 73 % à attendre le verrou (ObjectMonitor::enter) et 24 % dans le sleep qui simule la base. Le travail utile, validate et report, fait moins de 3 % de la largeur. Les quatre workers font la queue devant un seul verrou, et la fausse base ne sert qu’un thread à la fois.

Allocations : qui remplit la heap

Le mode alloc est précieux pour traquer la pression GC. Il montre où la heap est allouée, et pointe donc directement vers les boucles qui fabriquent trop d’objets temporaires. La mesure ne repose pas sur de l’instrumentation : la JVM prévient le profiler à chaque fois qu’un thread reçoit un nouveau bloc d’allocation (un TLAB) ou alloue un gros objet en dehors. L’overhead reste faible et le JIT n’est pas perturbé.

Flamegraph d'allocations : byte[] au sommet de Shop.report, boolean[] et int[] au sommet de Shop.validate

Profil d'allocations. La frame du sommet est la classe allouée, la largeur est en octets.

Ici la frame du haut n’est plus une méthode mais la classe de l’objet alloué, et la largeur mesure des octets. byte[] pèse 47 % des allocations et vient de Shop.report : chaque += copie la chaîne entière dans un nouveau tableau. boolean[] pèse 23 % et vient de Pattern.compile : chaque compilation de la regex fabrique ses tables de caractères. En quinze secondes, l’application a alloué 3,9 Go.

Deux options utiles : --alloc 1m règle l’intervalle d’échantillonnage (un échantillon par mégaoctet alloué), et --live ne garde que les objets encore vivants à la fin de la session, ce qui en fait un détecteur de fuite léger.

Locks : qui attend qui

Le mode lock mesure le temps passé à attendre l’entrée dans un bloc synchronized ou un Lock. La frame du haut est la classe du verrou, et la largeur est en nanosecondes d’attente.

Flamegraph de locks : une seule pile, java.lang.Object au sommet de Shop.save

Profil de locks. Un seul verrou, un seul endroit.

Difficile de faire plus clair. Un seul verrou, de type java.lang.Object, pris dans Shop.save. La sortie texte donne l’ampleur : 44 secondes d’attente cumulée sur une fenêtre de quinze secondes. Quatre threads, dont trois attendent en permanence. L’option --lock 10ms permet d’ignorer les attentes courtes et de ne garder que celles qui comptent.

Corriger, puis mesurer à nouveau

Les trois corrections sont celles qu’on imagine : compiler la regex une seule fois dans un champ static, construire le rapport avec un StringBuilder, et retirer le verrou global pour que chaque worker parle à la base de son côté.

static final Pattern EMAIL = Pattern.compile("^[\\w.+-]+@[\\w-]+\\.[\\w.]+$");

static String report(Order order) {
    StringBuilder out = new StringBuilder();
    for (int i = 0; i < order.lines(); i++) {
        out.append("line ").append(i).append(';');
    }
    return out.toString();
}

static void save(Order order, String report) {
    fakeDbCall(report);
}

Le débit passe de 710 à 2 930 commandes par seconde, quatre fois plus :

2934 commandes/s
2959 commandes/s
2908 commandes/s

Et on reprofile, dans les mêmes conditions, pour vérifier que le profil raconte bien la même histoire.

Flamegraph CPU après correction : ShopFixed.validate est réduit à Matcher.match, ShopFixed.save est dominé par Thread.sleep

Profil CPU après correction. Pattern.compile a disparu, le sleep de la base est devenu visible.

Pattern.compile a disparu. validate contient maintenant Matcher.match, le vrai travail, pour 31 % du CPU. report est passé à 17 %, et save est devenu un Thread.sleep : le temps de la base, qu’on ne corrigera pas dans ce programme. Le profil de locks est vide, zéro échantillon. Les allocations tombent à 1,2 Go sur quinze secondes, pour quatre fois plus de commandes traitées. Par commande, c’est treize fois moins de mémoire allouée.

C’est la vraie boucle du profiling : mesurer, corriger, mesurer à nouveau. Le second profil dit ce qui est devenu le plus large, et ici c’est l’aval.

Les formats de sortie

Le format se choisit avec -o, ou par l’extension du fichier donné à -f :

FormatCe qu’on obtient
flamegraph (.html)Le flamegraph interactif, un seul fichier, sans dépendance
flatLes méthodes au sommet de la pile, triées par échantillons
tracesLes piles complètes, les plus fréquentes d’abord
collapsedUne pile par ligne, pour les scripts du projet FlameGraph
treeUn arbre d’appels HTML, dépliable
jfr (.jfr)Un enregistrement JFR, lisible dans JDK Mission Control

Quelques options changent la forme du résultat sans changer la mesure. -t sépare les piles par thread. -s utilise des noms de classes courts. --reverse inverse le graphe pour partir des feuilles. --minwidth 1 masque les frames sous 1 %. -I et -X gardent ou excluent les piles qui contiennent un motif, avec des jokers : -I '*worker*', -X '*Compile*'. --title change le titre du HTML.

Piloter une session

asprof -d 30 lance, attend et arrête. Pour une session plus longue, ou pilotée depuis un script, on sépare les étapes :

asprof start -e cpu Shop           # démarre, rend la main
asprof status Shop                 # "Profiling is running for 5 seconds"
asprof dump -o flat -f now.txt Shop   # sort un résultat sans arrêter
asprof stop -f profile.html Shop   # arrête et écrit le fichier final

Pour du profiling continu, --loop 1h -f /var/log/profile-%t.jfr écrit un fichier par heure, %t étant remplacé par la date et l’heure. C’est ce que font sous le capot la plupart des outils de profiling continu, comme Pyroscope.

Avoir des stacks justes : DebugNonSafepoints

Pour que les frames Java soient attribuées au bon endroit, et pas recalées sur le safepoint le plus proche, lancez la JVM avec :

-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints

Sans ça, le code inliné par le JIT peut être mal localisé, et certaines petites méthodes inlinées n’apparaissent pas du tout. Ces deux flags n’ont pas de coût mesurable sur les perfs, autant les activer par défaut sur tout environnement que vous comptez profiler. Quand l’agent est attaché à chaud sur une JVM lancée sans ces flags, le profiler active l’information de debug lui-même, mais seulement pour les méthodes compilées après son arrivée.

Permissions et conteneurs

perf_events demande un accès au noyau. Sur une machine Linux classique, il faut en général :

sysctl kernel.perf_event_paranoid=1   # autorise le profiling user-space
sysctl kernel.kptr_restrict=0         # symboles du noyau dans les stacks

Dans un conteneur, c’est une autre histoire. Le conteneur de notre exemple tournait avec perf_event_paranoid à 4, et le profil seccomp par défaut de Docker bloque de toute façon l’appel perf_event_open. Pourtant, asprof -e cpu a fonctionné sans se plaindre. La raison : dans les versions récentes, quand perf_events n’est pas disponible, le mode cpu bascule tout seul sur un moteur de secours, ctimer, qui repose sur un timer POSIX et ne demande aucune permission. Le seul signe visible, c’est l’absence de frames du noyau dans le graphe.

Pour s’en rendre compte, il suffit de demander un événement qui n’existe que dans perf_events :

$ asprof -d 5 -e cache-misses Shop
[WARN] Kernel symbols are unavailable due to restrictions. Try
  sysctl kernel.perf_event_paranoid=1
  sysctl kernel.kptr_restrict=0
[WARN] perf_event_open for TID 246 failed: Operation not permitted
...
[ERROR] Perf events unavailable. Try --fdtransfer or --all-user option or 'sysctl kernel.perf_event_paranoid=1'

Trois façons de s’en sortir, par ordre de simplicité. Accepter ctimer, ce qui suffit pour profiler du code applicatif. Lancer le conteneur avec --security-opt seccomp=unconfined et parfois --cap-add SYS_ADMIN, si on contrôle le déploiement. Ou utiliser --fdtransfer, qui fait ouvrir les descripteurs perf par un process privilégié et les transmet à la JVM non privilégiée. Sur macOS, il n’y a pas de perf_events du tout : le mode cpu y repose sur itimer, et seul le code user-space est visible.

Reste la question de l’accès à la JVM. Trois situations :

Deux erreurs classiques à l’attache. Could not start attach mechanism veut dire que le socket /tmp/.java_pidNNN n’est pas accessible : il a été effacé par un nettoyage de /tmp, ou le /tmp du profiler n’est pas celui de la JVM, ou la JVM a été lancée avec -XX:+DisableAttachMechanism. Et Failed to change credentials veut dire que le profiler ne tourne pas sous le même utilisateur que la JVM, ce que le mécanisme d’attache exige.

Enfin, un détail qui saute aux yeux sur les captures de cet article : des frames nommées /usr/lib/aarch64-linux-gnu/libc.so.6. La libc de l’image Docker est livrée sans symboles, alors le profiler affiche le nom de la bibliothèque à la place du nom de la fonction. On sait qu’on est dans la libc, pas dans quelle fonction. Pour du code applicatif, ça ne gêne pas : les frames Java en dessous sont intactes.

Profiler dès le démarrage

Pour capturer ce qui se passe au boot, ou pour intégrer le profiling dans un run automatisé, on attache l’agent directement :

java -agentpath:/opt/async-profiler/lib/libasyncProfiler.so=start,event=cpu,file=profile.jfr \
     -jar app.jar

Les options sont les mêmes qu’en ligne de commande, séparées par des virgules. L’agent voit alors toutes les méthodes compilées depuis le début, avec l’information de debug complète.

Tout enregistrer en JFR

Un seul fichier HTML ne contient qu’un seul événement. Pour mesurer CPU, wall-clock, allocations et locks en même temps, la sortie doit être en JFR :

asprof -d 30 --all -f all.jfr Shop

--all active cpu, wall, alloc, live, lock et nativemem ensemble. Le fichier s’ouvre dans JDK Mission Control, et jfr summary all.jfr en donne le contenu :

 Event Type                          Count  Size (bytes)
=========================================================
 profiler.Free                       27374        492732
 jdk.JavaMonitorEnter                 7061        169464
 jdk.ObjectAllocationInNewTLAB        5025         93986
 profiler.WallClockSample             1704         28225
 jdk.ExecutionSample                   157          2158

Pour en tirer un flamegraph, jfrconv convertit un enregistrement en HTML, un événement à la fois :

jfrconv --cpu   -o html all.jfr cpu.html
jfrconv --alloc -o html all.jfr alloc.html
jfrconv --lock  -o html all.jfr lock.html

Ça marche aussi avec un enregistrement JFR produit par la JVM elle-même, sans async-profiler. Et avec --diff, jfrconv compare deux profils et colore ce qui a grossi ou rétréci, ce que l’article sur les flamegraphs montre sur notre exemple.

Et la mémoire native ?

Depuis la version 4, le mode nativemem intercepte malloc et free. Il sert quand le RSS du process monte alors que la heap Java va bien : un driver JDBC natif, une lib de compression, des DirectByteBuffer. La sortie va en JFR, et jfrconv --nativemem --leak ne garde que les allocations jamais libérées. C’est le complément naturel de l’article sur la mémoire hors-heap.

async-profiler ou JFR ?

Les deux échantillonnent, les deux tournent en production. JFR est intégré au JDK, ne demande aucun binaire externe, et enregistre bien plus que des stacks : GC, compilation, I/O, exceptions. C’est le bon choix pour un enregistrement de fond, toujours actif.

async-profiler est meilleur sur les stacks elles-mêmes. Il voit les frames natives et celles de la JVM, ne souffre pas du safepoint bias sur le CPU, et sort un flamegraph en une commande. Le mode wall n’a pas d’équivalent aussi simple dans JFR. Pour répondre vite à « pourquoi ce service est lent en ce moment », c’est lui.

Virtual threads et coroutines

Sur Java 21 et plus, async-profiler voit le code qui tourne dans un virtual thread. Mais un virtual thread qui attend est démonté de son carrier : il n’est sur aucune pile, et le mode wall ne le montre pas. Les attentes et le pinning se diagnostiquent plutôt avec JFR, comme expliqué dans l’article sur les virtual threads.

Pour les coroutines Kotlin, le profil CPU est juste, mais une coroutine suspendue n’est sur aucune pile. Le mode wall montre les threads du dispatcher en attente, pas la coroutine qui attend. L’article dédié explique comment retrouver l’information.

En résumé

asprof -d 30 -f profile.html <pid> suffit pour un premier profil CPU. Le mode wall avec -t et un filtre -I trouve les attentes, le mode alloc trouve la pression GC, le mode lock trouve les verrous disputés.

Lancez vos JVM avec -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints. En conteneur, cpu bascule tout seul sur ctimer, sans frames du noyau, et ça suffit presque toujours.

Sur notre exemple, trois profils ont trouvé trois problèmes en moins d’une minute de mesure. Après correction, le débit a été multiplié par quatre, et le second profil montre que le plafond est maintenant en aval.

Et après ?

Vous avez un profile.html sous les yeux. Un flamegraph se lit vite une fois qu’on connaît les règles du jeu, et c’est justement le sujet de l’article suivant : Comment lire un flamegraph.