JDK Flight Recorder en production : enregistrer, lire, automatiser
JDK Flight Recorder (JFR) est inclus dans le JDK. Il n’y a rien à installer. Il enregistre ce qui se passe dans la JVM : les GC, les locks, les exceptions, les lectures et écritures, et les stacks des threads. Il est prévu pour tourner en production.
Souvent, on ne l’utilise qu’après un incident, avec une interface graphique. Pourtant, il peut être utilisé en ligne de commande, avec deux outils du JDK : jcmd pour lancer et arrêter un enregistrement, jfr pour le lire.
Pour montrer comment utiliser JFR, cet article s’appuie sur une petite application qui contient quatre problèmes. Tous les tests ont été faits sur JDK 25. Les enregistrements de l’application ont été faits sur Temurin 25.0.4, dans un conteneur Linux à 4 CPU. La mesure du coût, les tests d’arrêt, JFR.dump, les événements personnalisés, RecordingStream et jfr scrub ont tourné sur OpenJDK 25.0.1, sur un Mac.
Ce que JFR enregistre
JFR enregistre des événements. Chaque événement a un type, une date, souvent une durée, le thread qui l’a produit et, selon le type, une stack trace.
Il y en a trois familles :
- les événements avec une durée, comme une attente sur un lock ou une écriture de fichier. Ils ont un seuil. Si l’événement est plus court que le seuil, JFR ne le garde pas.
- les événements périodiques, comme la charge CPU ou l’état de la heap. JFR les enregistre à intervalle fixe.
- les échantillons, comme les stacks des threads actifs. JFR en prend un nombre limité par seconde.
Un enregistrement contient près de 200 types d’événements. La plupart restent vides, parce que rien ne les a déclenchés.
L’application de l’exemple
Quatre threads worker traitent des commandes en boucle. Pour chaque commande, le programme lit une quantité, crée une facture d’une centaine de lignes, l’écrit dans un journal d’audit, puis la garde dans un historique.
public class Orders {
static final Object AUDIT = new Object();
static final List<String> HISTORY = new ArrayList<>();
static Writer auditLog; // un BufferedWriter sur /tmp/audit.log
// Problème 1 : une exception sert de contrôle de flux.
static int quantity(String raw) {
try {
return Integer.parseInt(raw);
} catch (NumberFormatException e) {
return 1;
}
}
// Problème 2 : String.format dans une boucle.
static String invoice(int lines) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < lines; i++) {
sb.append(String.format("%05d;%-20s;%8.2f%n", i, "article-" + i, i * 1.5));
}
return sb.toString();
}
// Problème 3 : l'écriture d'audit se fait sous un lock global.
static void audit(String invoice) throws IOException {
synchronized (AUDIT) {
auditLog.write(invoice);
auditLog.flush();
try { Thread.sleep(5); } catch (InterruptedException e) {}
}
}
// Problème 4 : un historique qui ne se vide jamais.
static void remember(String invoice) {
synchronized (HISTORY) {
HISTORY.add(invoice.substring(0, 64) + System.nanoTime());
}
}
}Le Thread.sleep(5) simule un disque lent. Un tiers des quantités sont vides ou invalides, et chacune lève une exception. Le thread principal affiche le throughput toutes les cinq secondes :
162 commandes/s
164 commandes/s
165 commandes/sEnregistrer dès le démarrage de la JVM
Le flag -XX:StartFlightRecording démarre un enregistrement en même temps que la JVM :
java -XX:StartFlightRecording:duration=20s,filename=orders.jfr -cp classes Orders 4La JVM affiche ce message au démarrage :
[0.597s][info][jfr,startup] Started recording 1. The result will be written to:
[0.597s][info][jfr,startup]
[0.597s][info][jfr,startup] /work/orders.jfrLe throughput ne change pas : environ 164 commandes par seconde, avec et sans JFR. Après vingt secondes, le fichier fait 394 ko.
Sans le paramètre duration, l’enregistrement continue jusqu’à l’arrêt de la JVM. Le message donne alors la commande pour récupérer les données : Use jcmd <pid> JFR.dump name=1 to copy recording data to file.
Ou sans redémarrer la JVM en utilisant jcmd
Le flag n’est pas obligatoire. Sur une JVM déjà lancée, jcmd démarre un enregistrement :
jcmd <pid> JFR.start name=prod settings=profile maxage=10mStarted recording 1.
Use jcmd 465 JFR.dump name=prod filename=FILEPATH to copy recording data to file.Quatre commandes couvrent l’usage courant :
jcmd <pid> JFR.check # les enregistrements en cours
jcmd <pid> JFR.view hot-methods # lire sans sortir de fichier
jcmd <pid> JFR.dump name=prod filename=/tmp/dump.jfr # copier les données sur disque
jcmd <pid> JFR.stop name=prod # arrêterJFR.check affiche Recording 1: name=prod maxage=10m (running). JFR.view affiche les données en cours dans le terminal. JFR.dump écrit les données sur disque, sans arrêter l’enregistrement.
Lire l’enregistrement sans interface graphique : jfr view
D’abord, jfr summary donne le nombre d’événements par type. Voici les lignes utiles pour nos vingt secondes :
Event Type Count Size (bytes)
=============================================================
jdk.ObjectAllocationSample 2926 41404
jdk.JavaExceptionThrow 1137 17164
jdk.ExecutionSample 83 892
jdk.JavaMonitorEnter 24 562
jdk.GarbageCollection 23 484
jdk.FileWrite 2 65Pour voir le détail, jfr view propose des vues prêtes à l’emploi. jfr help view en liste près de 80, en trois groupes : la JVM, l’environnement et l’application. Voici les vues qui montrent nos trois premiers problèmes.
hot-methods : où le CPU travaille
jfr view hot-methods orders.jfrMethod Samples Percent
----------------------------------------------------------------- ------- -------
java.util.Formatter.parse(String) 7 8.43%
java.lang.AbstractStringBuilder.append(char) 7 8.43%
Orders.lambda$main$0(String[]) 5 6.02%
java.util.Formatter$FormatSpecifierParser.parse() 5 6.02%
java.util.Formatter$FormatSpecifier.print(Formatter, int, Locale) 4 4.82%
java.util.Formatter.format(Locale, String, Object[]) 4 4.82%Cette vue compte la méthode en haut de la stack au moment de l’échantillon. C’est pour cela que Orders.invoice n’apparaît pas. La liste montre les méthodes de java.util.Formatter qu’elle appelle. C’est le problème 2 : String.format analyse le format à nouveau pour chaque ligne.
Il y a seulement 83 échantillons en vingt secondes. C’est normal. jdk.ExecutionSample ne prend que les threads qui exécutent du code Java. Or nos threads passent la plupart de leur temps à attendre le lock.
contention-by-site : quel code attend un lock
jfr view contention-by-site orders.jfrStackTrace Count Avg. Max.
--------------------------------------------------- ----- ------- -------
Orders.audit(String) 23 26.7 ms 39.2 ms
jdk.jfr.internal.PlatformRecorder.periodicTask() 1 22.2 ms 22.2 msC’est le problème 3. Les threads attendent en moyenne 26,7 ms pour entrer dans audit. La deuxième ligne vient de JFR lui-même, et on peut l’ignorer.
Pourtant, 23 attentes en vingt secondes, c’est peu pour quatre threads et un seul lock. La section sur les seuils explique pourquoi.
exception-by-site : qui lève des exceptions
jfr view exception-by-site orders.jfrMethod Count
--------------------------------------------------------------- -----
java.lang.NumberFormatException.forInputString(String, int) 1,131
java.lang.invoke.MethodHandleNatives.resolve(MemberName, ...) 9C’est le problème 1 : 1 131 exceptions en vingt secondes, soit environ 57 par seconde. Sur JDK 25, jdk.JavaExceptionThrow est actif par défaut, avec une limite de 100 événements par seconde. Au-dessus de cette limite, JFR n’en garde qu’une partie.
allocation-by-class et gc : la pression mémoire
jfr view allocation-by-class orders.jfrObject Type Allocation Pressure
------------------------------------------------- -------------------
byte[] 43.89%
java.util.Formatter$FormatSpecifier 10.87%
java.lang.Object[] 7.14%
java.lang.StringBuilder 7.14%
java.lang.String 5.86%
java.util.Formatter$FixedString 4.67%On retrouve Formatter, car chaque appel à String.format crée de nouveaux objets. jfr view gc montre le résultat : environ une collection young par seconde, avec des pauses de 1 à 5 ms environ :
Start GC ID Type Heap Before GC Heap After GC Longest Pause
-------- ----- --------------------------- -------------- ------------- -------------
15:55:01 0 Young Garbage Collection 18.1 MB 3.6 MB 4.83 ms
15:55:01 1 Young Garbage Collection 16.6 MB 4.4 MB 5.23 ms
15:55:02 2 Young Garbage Collection 19.4 MB 4.2 MB 1.59 msIci, ce n’est pas grave. Pour lire les logs GC en détail, voir Lire les logs GC sans outil externe.
Les seuils : ce que JFR ne voit pas
La sortie de jfr summary affiche 2 événements jdk.FileWrite. Pourtant, l’application écrit dans le journal d’audit plus de 160 fois par seconde.
JFR n’enregistre pas tout, pour limiter son coût. Chaque événement avec une durée a un seuil. Une écriture de fichier est gardée seulement si elle dure plus d’une milliseconde. Nos écritures vont vers le système à chaque flush(), mais elles restent dans le cache du système de fichiers. Elles sont donc rapides, et JFR n’en a gardé que deux.
C’est la même chose pour les locks. Le seuil de jdk.JavaMonitorEnter est de 20 ms. JFR ne garde pas les attentes plus courtes.
Le JDK fournit deux configurations, default et profile. Voici le même test avec settings=profile, sur une dizaine de secondes :
StackTrace Count Avg. Max.
--------------------------------------------------- ----- ------- -------
Orders.audit(String) 1,665 18.3 ms 59.1 msOn passe de 23 attentes à 1 665. Avec default, seulement une douzaine d’attentes dépassaient 20 ms toutes les dix secondes. Presque toutes les attentes durent donc entre 10 et 20 ms. default ne les voit pas, profile les voit.
Voici les différences entre les deux, lues dans les fichiers default.jfc et profile.jfc du JDK 25 :
| Événement | default | profile |
|---|---|---|
jdk.ExecutionSample | toutes les 20 ms | toutes les 10 ms |
jdk.JavaMonitorEnter | seuil 20 ms | seuil 10 ms |
jdk.ThreadPark, jdk.ThreadSleep | seuil 20 ms | seuil 10 ms |
jdk.JavaExceptionThrow | 100 par seconde | 300 par seconde |
jdk.ObjectAllocationSample | 150 par seconde | 300 par seconde |
jdk.OldObjectSample | sans stack trace | avec stack trace |
Il faut donc lire un enregistrement avec prudence. Si un événement est absent, cela ne veut pas dire que rien ne s’est passé. Cela veut dire que rien n’a dépassé le seuil.
Régler ses propres seuils
jfr configure crée un fichier de configuration à partir de la configuration par défaut :
jfr configure locking-threshold=5ms memory-leaks=stack-traces --output prod.jfc
java -XX:StartFlightRecording:settings=prod.jfc,filename=custom.jfr ...locking-threshold change en une fois le seuil des locks, des park, des sleep et des wait. Avec --verbose, la commande affiche chaque réglage écrit.
On peut aussi mettre ces options directement dans le flag, sans fichier :
java -XX:StartFlightRecording:locking-threshold=5ms,filename=custom.jfr ...jfr help configure liste les options disponibles. Par exemple : gc, compiler, allocation-profiling, method-profiling, exceptions, memory-leaks, thread-dump, class-loading, et deux options nouvelles dans le JDK 25, method-timing et method-trace.
memory-leaks=stack-traces ajoute la stack trace aux objets qui restent longtemps dans la heap. Cette option permet de trouver le problème 4. Voici le résultat sur un enregistrement profile d’une dizaine de secondes :
jfr view memory-leaks-by-site dump1.jfrAlloc. Time Application Method Object Age Heap Usage
----------- ------------------------------------ ---------- ----------
15:55:59 N/A 10.3 s 3.1 MB
15:56:05 Orders.main(String[]) 3.86 s 4.2 MB
15:56:06 Orders.remember(String) 2.57 s 4.2 MBOrders.remember apparaît bien. La vue montre aussi d’autres lignes sans intérêt. Sur dix secondes, tous les objets encore en mémoire ressemblent à une fuite. Cette vue est utile sur un enregistrement long, quand la même méthode revient souvent. Pour confirmer une fuite, utilisez un heap dump : Diagnostiquer une fuite mémoire avec un heap dump.
Ce que ça coûte
À cause du sleep, notre application attend plus qu’elle ne calcule. Pour mesurer le coût de JFR, j’ai utilisé une autre version, sans pause dans le lock. Elle écrit dans /dev/null et ne garde pas d’historique. Les mesures ont été faites sur un Mac à 10 cœurs.
J’ai d’abord mesuré le throughput, avec et sans JFR. Le résultat n’était pas exploitable. Sans JFR, le throughput variait de 107 000 à 136 000 commandes par seconde d’un run à l’autre. Cette variation était plus grande que l’effet de JFR.
J’ai ensuite mesuré le temps pour une quantité de travail fixe. Quatre threads traitent 200 000 commandes chacun, puis la JVM s’arrête. J’ai fait six runs par mode, en alternant les modes :
| Mode | Temps moyen | Minimum | Maximum |
|---|---|---|---|
| sans JFR | 7,17 s | 6,26 s | 8,00 s |
default | 7,21 s | 6,05 s | 8,58 s |
profile | 7,56 s | 6,24 s | 8,40 s |
Avec default, la différence moyenne est de 0,5 %. C’est moins que la variation normale entre deux runs. Avec profile, la différence moyenne est de 5,4 %. Elle reste aussi plus petite que la variation entre deux runs du même mode.
Sur cette application, on ne peut pas mesurer le coût de default. Le coût de profile est un peu visible. Pour votre application, il faut mesurer avec votre propre charge.
Toujours actif en production
JFR est plus utile quand il tourne en permanence. En cas d’incident, les dernières minutes sont déjà enregistrées.
java -XX:StartFlightRecording:maxage=1h,maxsize=200m,dumponexit=true,filename=/var/log/app/app.jfr ...maxage et maxsize limitent les données gardées : une heure et 200 Mo au maximum. JFR stocke ses données dans un dossier de travail, le repository. On peut choisir ce dossier avec -XX:FlightRecorderOptions:repository=/chemin. dumponexit=true écrit le fichier quand la JVM s’arrête.
J’ai testé ce dernier point, car une JVM de production ne s’arrête pas toujours normalement.
| Arrêt | Résultat |
|---|---|
SIGTERM | fichier écrit, 350 ko |
OutOfMemoryError qui tue le seul thread, la JVM sort | fichier écrit, 388 ko |
OutOfMemoryError avec -XX:+ExitOnOutOfMemoryError | fichier vide, 0 octet |
kill -9 | fichier vide, 0 octet |
Le cas ExitOnOutOfMemoryError est important, car ce flag est courant en conteneur. La JVM s’arrête tout de suite, sans exécuter dumponexit. Le fichier existe, mais il est vide, comme après un kill -9.
Après un kill -9 ou un ExitOnOutOfMemoryError, le repository contient un fichier. Mais jfr ne peut pas le lire :
jfr summary: could not read recording at .../2026_09_23_18_28_12.jfr. Recording file is stuck in locked stream state.Autre point sur l’OutOfMemoryError : l’erreur n’apparaît pas comme événement. jfr view jdk.JavaErrorThrow affiche No events found. Il faut regarder les GC. Juste avant l’erreur, une collection old ne libère presque rien :
18:25:09 16 Old Garbage Collection 63.5 MB 60.8 MB 6.08 msLes deux dernières collections vident la heap. Le thread main est arrêté, donc sa liste n’est plus utilisée et le GC peut la supprimer.
En pratique, il faut donc récupérer l’enregistrement avant l’arrêt de la JVM. Lancez jcmd <pid> JFR.dump filename=... quand la latence augmente, quand une alerte se déclenche, ou avant de redémarrer un pod.
Une remarque sur JFR.dump. Il accepte begin=-10s ou maxage=10s pour garder seulement la fin. Mais JFR stocke ses données par blocs, les chunks, et un dump contient toujours des chunks entiers. Sur une JVM lancée depuis 60 secondes, JFR.dump begin=-10s a renvoyé les 60 secondes. Le découpage se fait par chunk, pas à la seconde.
Chronométrer une méthode sans redéployer
JDK 25 ajoute deux options, method-timing et method-trace. La première compte les appels d’une méthode et mesure leur durée. On peut l’activer au démarrage :
java "-XX:StartFlightRecording:method-timing=Orders::invoice;Orders::audit,duration=10s,filename=timing.jfr" ...
jfr view method-timing timing.jfrLes guillemets sont nécessaires. Le point-virgule sépare les méthodes, et sans guillemets le shell le lit comme la fin de la commande.
Timed Method Invocations Minimum Time Average Time Maximum Time
------------------------- ----------- ------------ ------------ ------------
Orders.audit(String) 1,644 5.100000 ms 23.900000 ms 37.900000 ms
Orders.invoice(int) 1,648 0.048300 ms 0.209000 ms 16.500000 msSur dix secondes, audit prend 23,9 ms en moyenne, en comptant l’attente du lock. invoice prend 0,2 ms. Le temps est donc perdu dans le lock, pas dans la création de la facture.
L’option fonctionne aussi sur une JVM déjà lancée :
jcmd <pid> JFR.start method-timing=Orders::invoice duration=8s filename=/tmp/live-timing.jfrTimed Method Invocations Minimum Time Average Time Maximum Time
------------------------- ----------- ------------ ------------ ------------
Orders.invoice(int) 1,318 0.043500 ms 0.181000 ms 4.290000 msIl n’y a pas de code à ajouter et pas de redéploiement. C’est un moyen simple de savoir si une méthode est lente en production.
Le temps CPU, encore expérimental
JDK 25 ajoute aussi un nouveau type d’échantillon, basé sur le temps CPU. Il existe seulement sur Linux. Il est expérimental et désactivé par défaut :
jcmd <pid> JFR.start "jdk.CPUTimeSample#enabled=true" duration=8s filename=/tmp/cputime.jfr
jfr view cpu-time-hot-methods /tmp/cputime.jfr Java Methods that Execute the Most from CPU Time Sampler (Experimental)
Method Samples Percent
--------------------------------------------------------------- ------- -------
java.io.FileOutputStream.writeBytes(byte[], int, int, boolean) 5 11.63%
Orders.lambda$main$0(String[]) 5 11.63%
java.lang.AbstractStringBuilder.append(String) 5 11.63%
java.lang.AbstractStringBuilder.append(char) 4 9.30%FileOutputStream.writeBytes est en première ligne. C’est une méthode native, et elle n’était pas dans les 25 lignes de hot-methods plus haut. jdk.ExecutionSample ne prend que les threads qui exécutent du code Java. Les threads en code natif ont un autre événement, jdk.NativeMethodSample, qui les compte même quand ils attendent. Le nouvel échantillon compte seulement le temps CPU utilisé, code natif compris. Le titre de la vue indique qu’il est encore expérimental.
Vos propres événements
Une application peut aussi créer ses propres événements. Il suffit d’une classe qui étend jdk.jfr.Event :
@Name("shop.Order")
@Label("Commande")
@Category("Shop")
@StackTrace(false)
public class OrderEvent extends Event {
@Label("Client")
String customer;
@Label("Lignes")
int lines;
}On l’utilise autour du code à mesurer :
OrderEvent event = new OrderEvent();
event.begin();
traiter(commande);
event.customer = customer;
event.lines = lines;
event.commit();L’événement est actif par défaut. On le lit comme les autres :
jfr view shop.Order shop.jfr Commande
Start Time Duration Event Thread Stack Trace Client Lignes
---------- -------- -------------- ------------- -------- ------
18:22:15 45.1 ms main N/A alice 35
18:22:15 27.0 ms main N/A bob 18
18:22:15 63.0 ms main N/A carol 53Les annotations @Label donnent les titres des colonnes. L’événement contient des données métier : le client et le nombre de lignes. Il est dans le même fichier que les GC et les locks, avec la même échelle de temps. On peut donc comparer une commande lente avec les pauses GC du même moment.
Attention à un détail. Pour mettre un seuil sur votre propre événement, il faut un + devant son nom :
java "-XX:StartFlightRecording:+shop.Order#threshold=40ms,filename=shop40.jfr" ...Avec le +, JFR garde les 22 commandes sur 60 qui dépassent 40 ms. Sans le +, il garde les 60. Le réglage est ignoré, sans message d’erreur. Le + ajoute un réglage pour un événement qui n’est pas dans le fichier .jfc.
Lire JFR depuis l’application
RecordingStream lit les événements au moment où ils arrivent, dans la JVM elle-même :
RecordingStream rs = new RecordingStream();
rs.enable("shop.Order").withThreshold(Duration.ofMillis(40));
rs.onEvent("shop.Order", e ->
System.out.println("commande lente : " + e.getString("customer")
+ ", " + e.getInt("lines") + " lignes, " + e.getDuration().toMillis() + " ms"));
rs.startAsync();commande lente : carol, 53 lignes, 63 ms
commande lente : carol, 30 lignes, 40 ms
commande lente : alice, 48 lignes, 55 msÀ la place du println, on peut mettre à jour une métrique ou écrire une ligne de log. JFR applique le seuil de 40 ms, donc le code reçoit seulement les commandes lentes.
Pendant le test, la JVM ne s’arrêtait pas à la fin de main. La cause : le thread JFR Event Stream 1 n’est pas un thread daemon. Un rs.close() à la fin du programme corrige le problème. Sur un serveur qui tourne en continu, ce problème n’existe pas.
Avant d’envoyer un enregistrement
Un fichier JFR ne contient pas seulement des stacks. Il contient aussi les variables d’environnement, les propriétés système et la ligne de commande de la JVM. Voici un test avec un mot de passe dans une variable d’environnement et une clé en -D :
jfr print --events InitialEnvironmentVariable app.jfr key = "DB_PASSWORD"
value = "s3cr3t-db"La propriété app.api.key apparaît aussi, et une deuxième fois dans le champ jvmArguments de jdk.JVMInformation.
Avant de joindre un fichier à un ticket, utilisez jfr scrub pour retirer ces événements :
jfr scrub --exclude-events InitialEnvironmentVariable,InitialSystemProperty,JVMInformation app.jfr clean.jfrRemoved events:
jdk.InitialEnvironmentVariable 68/68
jdk.InitialSystemProperty 16/16
jdk.JVMInformation 1/1Les deux secrets étaient lisibles dans le fichier d’origine. Ils ne sont plus dans le fichier nettoyé. Le reste de l’enregistrement ne change pas.
En résumé
JFR est inclus dans le JDK. -XX:StartFlightRecording le démarre avec la JVM, et jcmd <pid> JFR.start le démarre sur une JVM déjà lancée. jfr view lit les fichiers sans interface : hot-methods, contention-by-site, exception-by-site, allocation-by-class, gc.
JFR garde seulement ce qui dépasse un seuil. Avec default, une attente de 15 ms sur un lock n’apparaît pas. Utilisez profile, ou baissez le seuil avec locking-threshold.
Dans notre mesure, le coût de default est plus petit que la variation entre deux runs. Laissez JFR tourner avec maxage et maxsize, et récupérez les données avec JFR.dump avant l’arrêt de la JVM. dumponexit ne fonctionne pas après un kill -9 ou avec ExitOnOutOfMemoryError.
JDK 25 ajoute method-timing, qui mesure la durée d’une méthode sur une JVM déjà lancée. Il ajoute aussi un échantillon basé sur le temps CPU, encore expérimental.
Vos propres événements sont enregistrés avec ceux de la JVM. N’oubliez pas le + pour leurs réglages. Et utilisez jfr scrub avant de partager un fichier.
Et après ?
JFR montre ce qui s’est passé dans la JVM. Pour voir en détail où va le temps CPU, avec les frames natives et un flamegraph, utilisez async-profiler : Profiler la JVM avec async-profiler.