Lire un thread dump avec jstack
Quand une application JVM se fige, consomme tout le CPU sans raison apparente ou ralentit d’un coup, la première question est simple : que font les threads en ce moment ? jstack répond à cette question. C’est un outil livré avec le JDK qui imprime la pile d’appels de chaque thread d’un process Java vivant. Pas d’agent à installer, pas de redémarrage, pas de dépendance. Vous avez le PID, vous avez le dump.
Un thread dump est une photo. Il fige l’état de tous les threads à un instant donné : ce qu’ils exécutent, sur quel verrou ils attendent et dans quel état ils se trouvent. Bien lu, il dit en quelques secondes si l’application est coincée sur un lock, en attente d’une I/O, ou en train de tourner pour de vrai.
Trouver le bon process
jstack a besoin du PID de la JVM cible. jps, lui aussi dans le JDK, liste les process Java avec leur classe principale :
$ jps -l
9850 DeadlockDemo
9123 org.springframework.boot.loader.JarLauncher
Ensuite on attache jstack au PID :
jstack 9850
Le dump part sur la sortie standard. En général on le redirige dans un fichier pour le relire à tête reposée :
jstack -l 9850 > dump-1.txt
L’option -l (long listing) ajoute les informations de verrou. On verra plus bas pourquoi elle vaut le coup presque tout le temps.
Anatomie d’une ligne de thread
Chaque thread commence par une ligne d’en-tête, suivie de sa pile. Voici un thread applicatif réel :
"worker-1" #25 [25091] prio=5 os_prio=31 cpu=0.18ms elapsed=13.48s tid=0x0000000810743800 nid=25091 waiting for monitor entry [0x00000001719c2000]
java.lang.Thread.State: BLOCKED (on object monitor)
at DeadlockDemo.lambda$main$0(DeadlockDemo.java:8)
- waiting to lock <0x00000003ce7631c0> (a java.lang.Object)
- locked <0x00000003ce7631b0> (a java.lang.Object)
at java.lang.Thread.run(java.base@25.0.1/Thread.java:1474)
Décodons l’en-tête, champ par champ :
"worker-1": le nom du thread. Nommer ses threads change tout pour le diagnostic. Un pool qui s’appellehttp-nio-8080-exec-3se repère du premier coup d’œil,Thread-47non.#25: l’identifiant interne du thread dans la JVM.[25091]etnid=25091: l’identifiant du thread au niveau du système d’exploitation. C’est ce numéro qui permet de relier un thread Java à une ligne detop -H. Selon le JDK et l’OS, il peut être affiché en hexadécimal, pensez à convertir.prioetos_prio: priorités Java et système. Rarement utiles.cpu: temps CPU consommé par ce thread depuis sa création.elapsed: depuis combien de temps il existe.tid: l’adresse de la structure interne du thread dans la JVM.waiting for monitor entry: l’état résumé, repris en clair juste en dessous.
La ligne suivante, java.lang.Thread.State, est la plus importante du lot.
Comprendre les états
Un thread est toujours dans l’un de ces états, et chacun oriente le diagnostic dans une direction différente.
RUNNABLE: le thread exécute du code Java ou du code natif. Attention, un thread bloqué sur une lecture réseau apparaît souvent RUNNABLE, parce que la JVM ne sait pas que l’appel natif attend. Une pile RUNNABLE arrêtée sursocketRead0veut dire « en attente du réseau », pas « occupé à calculer ».BLOCKED (on object monitor): le thread veut entrer dans un blocsynchronizedmais le moniteur est tenu par un autre thread. Plusieurs threads BLOCKED sur le même verrou, c’est un point de contention.WAITING (on object monitor): le thread a appeléObject.wait(), ou attend sur un lockjava.util.concurrent. Il dort jusqu’à ce qu’on le réveille.TIMED_WAITING: pareil, mais avec un délai (Thread.sleep,wait(timeout),park(timeout)).
Le réflexe sur un dump d’application figée : on cherche d’abord les threads BLOCKED, puis on regarde qui tient le verrou qu’ils attendent.
L’option -l : voir les verrous
Reprenons la pile de worker-1. Deux lignes commençant par un tiret s’y sont glissées :
- waiting to lock <0x00000003ce7631c0> (a java.lang.Object)
- locked <0x00000003ce7631b0> (a java.lang.Object)
locked <...> veut dire « ce thread tient ce moniteur ». waiting to lock <...> veut dire « il veut celui-là mais ne l’a pas encore ». Les identifiants entre chevrons (0x00000003ce7631c0) sont les adresses des objets qui servent de verrou. C’est par elles qu’on relie deux threads : si le thread A attend l’objet que le thread B a verrouillé, on tient le fil.
-l ajoute aussi, sous chaque thread, la liste des « ownable synchronizers », c’est-à-dire les locks java.util.concurrent (comme ReentrantLock) détenus :
Locked ownable synchronizers:
- None
Sans -l, ces verrous-là n’apparaissent pas, et une contention sur un ReentrantLock passe inaperçue. D’où le conseil : prenez l’habitude de toujours mettre -l.
Détecter un deadlock
C’est l’un des cas où jstack fait gagner le plus de temps. La JVM détecte elle-même les deadlocks sur moniteurs et les écrit en clair, à la fin du dump :
Found one Java-level deadlock:
=============================
"worker-1":
waiting to lock monitor 0x00000008107657a0 (object 0x00000003ce7631c0, a java.lang.Object),
which is held by "worker-2"
"worker-2":
waiting to lock monitor 0x00000008107656c0 (object 0x00000003ce7631b0, a java.lang.Object),
which is held by "worker-1"
Found 1 deadlock.
Tout est dit : worker-1 attend un objet tenu par worker-2, et worker-2 attend un objet tenu par worker-1. Aucun des deux ne lâchera. La JVM nomme les deux threads, les deux objets, puis imprime les piles complètes pour qu’on remonte à la ligne de code fautive. Ici, les deux threads prennent deux verrous dans un ordre opposé, le bug classique.
Une limite à connaître : cette détection automatique ne couvre que les deadlocks sur moniteurs synchronized et sur locks java.util.concurrent. Un blocage logique, par exemple deux threads qui s’attendent via une file ou une condition, ne sera pas signalé comme « deadlock ». Il faudra le lire à la main dans les états WAITING.
L’option -e : information étendue
Sur un JDK récent, -e ajoute des champs à l’en-tête de chaque thread :
"worker-1" #25 [25091] prio=5 os_prio=31 cpu=0.18ms elapsed=20.60s allocated=1336B defined_classes=2 tid=0x0000000810743800 nid=25091 ...
allocated donne le total alloué sur la heap par ce thread. Croisé avec plusieurs dumps espacés dans le temps, ça aide à repérer le thread qui produit le plus de déchets et met le GC sous pression.
Un seul dump ne suffit pas
Un thread dump est une photo, pas un film. Un thread vu RUNNABLE une fois peut très bien être en train de finir son travail normalement. Pour distinguer ce qui est réellement coincé de ce qui avance, prenez plusieurs dumps espacés de quelques secondes :
for i in 1 2 3 4 5; do
jstack -l 9850 > dump-$i.txt
sleep 2
done
Ensuite on compare. Un thread qui reste sur la même pile dans les cinq dumps est bloqué ou très lent. Un thread dont la pile change à chaque fois travaille. C’est cette comparaison, plus que le dump isolé, qui pointe le vrai problème.
Pour un pic de CPU, on combine avec l’outillage du système. Sur Linux, top -H -p <pid> montre la consommation par thread et donne l’identifiant système. On le convertit (souvent en hexadécimal) puis on cherche le nid correspondant dans le dump : la pile de ce thread montre la boucle qui mange le CPU.
Des motifs qui reviennent
Au bout de quelques diagnostics, on reconnaît des formes :
- Tous les threads d’un pool HTTP en BLOCKED ou WAITING sur la même ressource : une ressource est saturée en aval, par exemple un pool de connexions à la base épuisé. Les requêtes s’empilent en attente de
getConnection. - Un seul thread RUNNABLE qui consomme, les autres au repos : un point chaud CPU, une boucle qui tourne. C’est là qu’un profiler prend le relais.
- Beaucoup de threads en TIMED_WAITING sur du
park: un pool au repos qui attend du travail. C’est normal, pas un symptôme. - Une file de threads qui grossit dump après dump sur le même point d’entrée : un goulot d’étranglement qui ne se résorbe pas.
jstack ou jcmd ?
jstack fait une chose et la fait bien. L’outil que l’équipe OpenJDK met aujourd’hui en avant comme point d’entrée général est jcmd, qui regroupe beaucoup de diagnostics. Pour un thread dump :
jcmd 9850 Thread.print
jcmd 9850 Thread.print -l # avec les ownable synchronizers
La sortie est la même que celle de jstack. jcmd a l’avantage de donner accès à d’autres commandes (info heap, GC, classes chargées) avec le même outil. Les deux marchent, prenez celui que vous préférez.
Quelques pièges
- Lancez jstack avec le même JDK et le même utilisateur que la JVM cible. Un écart de version ou de droits, et l’attache échoue.
- L’ancienne option
-F(force, via la Serviceability Agent) a disparu des JDK récents. Sur un process vraiment gelé qui ne répond plus à l’attache, on passe par un core dump etjhsdb. - En conteneur, jstack doit tourner dans le même namespace PID que la JVM, souvent depuis le conteneur lui-même. Le PID vu de l’hôte n’est pas celui vu dans le conteneur.
- Prendre un thread dump amène la JVM à un safepoint. L’impact est faible, mais sur une JVM déjà au bord, des dumps en rafale très serrée ajoutent un peu de pression. Quelques secondes d’écart suffisent.
Pour aller plus loin
jstack répond à la question « qui est bloqué et sur quoi ». Quand elle devient « qui brûle le CPU et dans quelle boucle », un profiler par échantillonnage est plus adapté : voir Profiler la JVM avec async-profiler et Comment lire un flamegraph.