Comment lire un flamegraph

Vous avez lancé un profiling, par exemple avec async-profiler, et vous voilà devant un flamegraph. C’est l’une des meilleures façons de comprendre où part le temps d’un programme, à condition de connaître la grille de lecture. Elle tient en quelques règles. Ensuite, on la met en pratique sur six graphes réels, pris sur la même application.

Ce que représente chaque axe

Un flamegraph agrège des milliers d’échantillons de stacks. Chaque rectangle est une frame, c’est-à-dire une méthode.

Les couleurs d’async-profiler

Le fichier HTML d’async-profiler colore chaque frame selon son type. La légende est accessible depuis le bouton ? en haut à gauche du graphe :

CouleurCe que c’est
VertMéthode Java compilée par le JIT (C2)
Vert clairMéthode Java compilée par C1
Vert pâleMéthode Java interprétée
CyanMéthode Java inlinée dans une autre
JauneCode C++ de la JVM elle-même
RougeCode natif (libc, JNI, la libjvm sans symboles)
OrangeNoyau Linux

Ça se lit vite avec l’habitude. Un empilement jaune sous votre code, c’est la JVM qui travaille pour vous (verrous, GC, JIT). Un plateau rouge tout en haut, c’est du natif : une copie de tableau, un appel système, une lib externe. Et beaucoup de vert pâle, c’est du code qui tourne encore en mode interprété, donc une application qui n’a pas fini de chauffer.

Deux modes changent la lecture du sommet. En mode allocation, la frame du haut est la classe de l’objet alloué, en cyan. En mode lock, c’est la classe du verrou.

Le piège classique : l’horizontale n’est pas le temps

C’est l’erreur qu’on voit le plus souvent. De gauche à droite, il n’y a pas de chronologie. Les frames d’un même niveau sont juste triées par ordre alphabétique pour regrouper les piles identiques. Une méthode tout à droite ne s’exécute pas « après » celle de gauche. Un flamegraph répond à la question « où passe le temps ? », pas à « dans quel ordre ? ». Pour de la chronologie, il faut un autre outil, une trace ou une timeline.

Un premier graphe, lu ensemble

L’application qui sert d’exemple est décrite dans l’article sur async-profiler. En deux mots : quatre threads worker traitent des commandes en boucle. Pour chaque commande, validate vérifie des adresses e-mail, report construit un texte, et save appelle une fausse base de données. Trois problèmes y sont plantés exprès. Voici le profil CPU, quinze secondes d’échantillonnage.

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

Profil CPU, avant correction. Le bloc du milieu est Shop.save, celui de droite Shop.validate.

On lit de bas en haut. Tout en bas, all, la totalité des échantillons. Juste au-dessus, Thread.run et Shop.work prennent presque toute la largeur : c’est normal, tout le travail part de là. Cette base large ne dit rien, sauf que le programme fait ce qu’on lui demande.

Le niveau suivant est celui qui compte. Shop.work se sépare en trois blocs : Shop.validate à droite, Shop.save au milieu, Shop.report à gauche. En survolant chacun, le graphe affiche sa part : 49 % pour validate, 21 % pour report, 18 % pour save. Voilà la priorisation, faite en trois survols.

Ensuite on monte. Au-dessus de validate, presque tout est dans Pattern.compile. La regex est compilée à chaque appel, et le programme y passe 36 % de son CPU. La frame Matcher.matches, celle qui fait le vrai travail, est minuscule à côté. Au-dessus de report, on traverse String$$StringConcat et String.getBytes, puis un plateau rouge : copy_byte_f, une copie mémoire native. C’est la signature d’une chaîne construite par concaténation dans une boucle. Au-dessus de save, du jaune : ObjectMonitor::enter, la JVM qui gère un verrou disputé.

Tout à gauche, une colonne étroite qui ne part pas de Thread.run : ce sont les threads du GC et de la JVM, 5 % du total. Et au-dessus de la regex, quelques tours jaunes, fines et hautes : OptoRuntime::new_array_C, le chemin lent de l’allocation, quand la JVM doit fournir un nouveau bloc mémoire au thread. Fines, donc pas chères. On les ignore.

En pratique : chercher les plateaux

La méthode qui marche, sur ce graphe comme sur les autres :

  1. Partir du haut et repérer les frames larges. Le sommet d’une pile, c’est le code qui était réellement en train de tourner quand l’échantillon a été pris (son « self time »). Un large plateau en haut, c’est du temps brûlé directement là. Premier suspect.
  2. Redescendre pour comprendre le chemin. En suivant une frame large vers le bas, on voit qui a mené jusque-là. Bien souvent le coupable n’est pas la feuille elle-même, mais le fait qu’on l’appelle beaucoup trop, depuis plus haut. copy_byte_f n’a rien à se reprocher. Shop.report, si.
  3. Ignorer les tours fines et isolées. Une pile étroite et très haute consomme peu : beaucoup d’appels imbriqués, mais peu de temps total. Pas une priorité.

La règle à garder en tête : la largeur dit combien ça coûte, la position en haut dit où c’est effectivement dépensé.

La vue inversée

Le graphe classique part des threads et monte vers les feuilles. Parfois on veut l’inverse : partir d’une feuille chaude et savoir qui l’appelle. C’est la vue inversée, obtenue avec --reverse à la génération, ou avec le premier bouton en haut à gauche du HTML (touche I). Elle s’affiche en « icicle », les piles pendent vers le bas.

Flamegraph CPU inversé : les feuilles sont en haut, les appelants en dessous

Le même profil CPU, inversé. Chaque colonne part d'une feuille et descend vers ses appelants.

On y voit copy_byte_f en haut, et en dessous la chaîne complète qui y mène jusqu’à Shop.report. Cette vue est utile quand une même méthode de bas niveau est appelée depuis plusieurs endroits, par exemple une sérialisation JSON ou une méthode equals appelée partout. Le graphe normal la découpe en dix petits blocs. La vue inversée les regroupe.

Chercher, zoomer, filtrer

Trois gestes rendent un gros graphe lisible.

La loupe (ou Ctrl+F) ouvre une recherche. On tape un mot ou une regex, les frames qui correspondent s’allument en magenta, et un compteur « Matched » affiche leur part totale. C’est le moyen le plus rapide de répondre à « combien coûte tout ce qui touche à la regex ? », même si c’est éparpillé.

Un clic sur une frame zoome dessus : elle prend toute la largeur, et les pourcentages sont recalculés par rapport à elle. Un clic sur all revient au départ.

Enfin, à la génération, --minwidth 1 masque les frames sous 1 %, et -I/-X gardent ou excluent les piles qui contiennent un motif. Sur une application avec deux cents threads, -I '*worker*' enlève tout ce qui n’est pas le vôtre.

Wall-clock : la largeur, c’est de l’attente

Le même graphe ne se lit pas pareil selon ce qui a été mesuré. Voici l’application profilée en mode wall-clock, tous threads confondus, avec l’option -t qui pose le nom du thread à la base de chaque pile.

Flamegraph wall-clock de tous les threads de la JVM : vingt-six colonnes de largeur égale, la plupart en rouge

Wall-clock, tous les threads. Chaque colonne est un thread, et toutes ont la même largeur.

Première surprise : vingt-six colonnes, toutes de la même largeur. En wall-clock, chaque thread reçoit un échantillon à intervalle fixe, qu’il travaille ou qu’il dorme. Un thread qui dort quinze secondes pèse donc autant qu’un thread qui calcule quinze secondes. Ici, la plupart des colonnes sont des threads de la JVM qui attendent : GC, compilateur, main qui dort, le listener d’attach. Les quatre colonnes de droite sont les worker. Le reste est du bruit.

D’où le réflexe : en wall-clock, on filtre. Le même profil avec -I '*worker*' :

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

Wall-clock, filtré sur les workers. Chaque worker passe l'essentiel de son temps dans Shop.save.

Là, ça parle. Chaque worker est presque entièrement sous Shop.save, 97 % de sa colonne. Au-dessus, une pile jaune et rouge : ObjectMonitor::enter, PlatformEvent::park, pthread_cond_wait. Le thread ne calcule pas, il attend un verrou, et ça fait 73 % du graphe. Une part plus mince, à droite de chaque colonne, est sous Thread.sleep : c’est la fausse base de données, 24 %. Et le vrai travail, validate et report ? Un liseré de quelques pixels, à gauche. Dans le profil CPU, ces deux méthodes faisaient 70 % du graphe. En wall-clock, elles font moins de 3 %. Les deux graphes sont justes. Ils ne répondent pas à la même question.

Sur un vrai service, les frames d’attente à connaître sont Unsafe.park (un pool de threads inactif, ou un Future.get), SocketRead ou socketRead0 (une réponse réseau), et ObjectMonitor::enter (un synchronized disputé). Une frame large de ce type se corrige en supprimant l’attente, pas en accélérant le code.

Allocations : la largeur, ce sont des octets

En mode allocation, la largeur ne mesure plus du temps mais des octets alloués. Et la frame du sommet est la classe allouée, pas une méthode.

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

Profil d'allocations. Sous byte[], la concaténation de chaînes ; sous boolean[], la compilation de la regex.

Deux plateaux cyan en haut. byte[], 47 % des octets, posé sur StringConcatHelper et Shop.report : chaque += copie la chaîne entière dans un nouveau tableau. boolean[], 23 %, posé sur Pattern$BitClass et Shop.validate : chaque compilation de la regex fabrique ses tables de caractères. Le graphe donne le quoi (la classe) et le (la méthode) d’un seul coup d’œil. C’est exactement ce dont on a besoin pour faire baisser la pression sur le GC, le sujet de l’article sur le tuning du GC.

Avant, après

Une fois les trois problèmes corrigés (regex compilée une seule fois, StringBuilder, plus de verrou global), on reprofile dans les mêmes conditions.

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

Profil CPU, après correction. Le débit est passé de 710 à 2 930 commandes par seconde.

Le bloc validate existe toujours, mais il ne contient plus que Matcher.match, le vrai travail. Pattern.compile a disparu. Le bloc report est devenu étroit. Et save est maintenant surtout du Thread.sleep : l’appel à la base. Ce plateau-là ne se corrigera pas dans ce programme. Le plafond est en aval, et c’est le graphe qui le dit.

C’est la lecture la plus utile d’un profil après optimisation : vérifier que le plateau visé a disparu, et regarder ce qui est devenu le plus large à sa place.

Quelques motifs qu’on reconnaît vite

Comparer deux profils

Pour comparer un avant et un après, jfrconv sait produire un flamegraph différentiel à partir de deux profils, au format JFR, HTML ou collapsed :

jfrconv --cpu --diff avant.jfr apres.jfr diff.html

Flamegraph différentiel : la forme du profil après correction, avec Shop.report en rouge et les frames de StringBuilder en jaune

Flamegraph différentiel, avant contre après. Rouge : plus d'échantillons qu'avant. Jaune : frames qui n'existaient pas avant.

Le graphe prend la forme du second profil, celui d’après. Chaque frame est colorée selon son écart avec le premier : rouge si elle a plus d’échantillons qu’avant, bleu si elle en a moins, gris si rien n’a bougé, jaune si elle n’existait pas du tout. Plus la couleur est intense, plus l’écart est grand, et le survol donne le delta exact. Ici, les frames de StringBuilder sous Shop.report sont jaunes : c’est du code nouveau. Et Pattern.compile n’apparaît pas, parce qu’une frame qui n’existe que dans le premier profil n’est pas dessinée. Pour voir ce qui a disparu, on refait le graphe en inversant les deux fichiers.

Une condition pour que ça marche : les deux profils doivent avoir été pris dans les mêmes conditions. Même durée, même charge, même événement. Sinon les écarts mesurent la différence de charge, pas la différence de code.

En résumé

Cherchez le large, partez du haut, ne lisez pas l’horizontale comme une horloge, et souvenez-vous de ce que l’événement profilé veut dire. En CPU, une frame large est du calcul. En wall-clock, c’est souvent une attente, et il faut filtrer les threads inactifs avant de lire. En allocation, ce sont des octets, et la frame du haut est une classe.

Les couleurs d’async-profiler sont une aide : vert pour Java, jaune pour la JVM, rouge pour le natif. La vue inversée et la recherche regroupent ce que le graphe normal éparpille. Et après une correction, on reprofile pour voir ce qui est devenu le plus large.

Si vous n’avez pas encore généré le vôtre : Profiler la JVM avec async-profiler.