Analyse de lenteurs grâce aux thread dumps Java
Le Principe #
Lorsque vous exécutez une application Java, il peut arriver que votre programme se bloque ou rencontre des problèmes de performances. Dans de tels cas, il peut être utile d'obtenir des informations sur l'état des threads de votre application pour diagnostiquer et résoudre les problèmes.
Java offre une méthode simple pour extraire l'état des threads sous forme de thread dump via l'exécution de la commande "kill -3". Lorsque cette commande est exécutée sur l'ID du processus concerné, un thread dump sera écrit dans la sortie standard (stdout).
Lorsqu'elle est disponible sur l'environnement concerné par le diagnostic, il est également possible d'utiliser la commande jstack à la place du "kill -3" pour envoyer le résultat vers un fichier dédié.
Bien entendu, il existe des outils très avancés tels que les APM (Application Performance Management) qui pourront identifier ces problèmes et aider à les résoudre de façon plus rapide. Toutefois, il n'est pas rare de se retrouver face un environnement où ces outils ne sont pas installés. Dans ce cas, le thread dump est toujours disponible pour venir en aide. C'est en quelque sorte un outil de premier secours à connaitre en cas d'urgence 🚨 😉
Préparation du coupable parfait #
Pour construire le coupable parfait, j'aurai pû créer un programme Java simple. Mais je veux vous montrer que ceci fonctionne également avec des applications plus complexes. Je vous propose donc de partir d'une application Spring Boot créé à partir de Spring Initializr avec une dépendance sur Spring Web.
Ainsi, nous allons créer un endpoint très simple qui appelle un service Business contenant une méthode normale et une méthode lente qui simulera un lourd traitement en dormant pendant dix secondes (oui, c'est très long 😅)
package org.dlemontagner.demo;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.stereotype.Controller;
import org.springframework.stereotype.Service;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.ResponseBody;
@SpringBootApplication
public class ThreaddumpApplication {
public static void main(String[] args) {
SpringApplication.run(ThreaddumpApplication.class, args);
}
@Controller
@ResponseBody
class DemoHttpController {
private final BusinessService businessService;
DemoHttpController(BusinessService businessService) {
this.businessService = businessService;
}
@GetMapping("/")
String business() {
businessService.doSlowBusiness();
return businessService.doBusiness();
}
}
@Service
class BusinessService {
public String doBusiness(){
return "Business Done";
}
public void doSlowBusiness(){
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}Création d'un thread dump #
Exécutons l'application Spring et attardons nous sur les logs de démarrage pour récupérer l'ID du processus (PID - ici 91902):
2023-07-03T15:30:15.384+02:00 INFO 91902 --- [ main] o.d.demo.ThreaddumpApplication : Starting ThreaddumpApplication using Java 20.0.1 with PID 91902 (/Users/dlemontagner/Documents/Dev/demo.threaddump/target/classes started by dlemontagner in /Users/dlemontagner/Documents/Dev/demo.threaddump)Lançons désormais une requête via httpie (mais vous pouvez également utiliser votre navigateur internet préféré). Puis, pendant que le traitement est en cours, nous allons lancer un kill -3 sur le PID récupéré ci-dessus.
http :8080 &
# Attendre une petite seconde
kill -3 91902Suite au kill -3, nous retrouverons le thread dump dans la sortie standard. Comme indiqué précédemment, il est possible de remplacer le "kill -3" par l'usage de la commande jstack. Ceci a l'avantage de permettre d'envoyer le résultat dans un fichier de notre choix:
jstack -l 91902 > thread_dump.logStructure d'un thread dump #
Regardons maintenant en détail le contenu d'un thread dump. Tout commence par l'en tête avec un timestamp, les informations de version sur la JVM ainsi qu'un bloc listant les threads SMR (Safe Memory Reclamation c'est à dire non internes à la JVM):
2023-07-03 14:56:06
Full thread dump OpenJDK 64-Bit Server VM (20.0.1 mixed mode, sharing):
Threads class SMR info:
_java_thread_list=0x000060000336c4e0, length=27, elements={
0x000000013d809200, 0x000000013d80ba00, 0x000000012d86b600, 0x000000013d80c000,
0x000000013e813000, 0x000000013e813600, 0x000000013e813c00, 0x000000013e817000,
0x000000013f03d800, 0x000000013e8aaa00, 0x000000013f97ba00, 0x000000013f1da000,
0x000000013f96f000, 0x000000013daada00, 0x000000013daad000, 0x000000013db46400,
0x000000013db46a00, 0x000000013db47000, 0x000000013db47600, 0x000000013db4b800,
0x000000013db4be00, 0x000000013e8ad600, 0x000000013e8c9c00, 0x000000013e8cd000,
0x000000013e8ca200, 0x000000012dafac00, 0x0000000129811e00
}Puis, chacun de ces threads est détaillé. En fonction de la version de JVM, les informations peuvent variées mais on y retrouve à minima:
- Le nom du thread
- L'ID du thread
- Un tag daemon qui ne sera présent que si le thread en question est un daemon
- La priorité du thread au sein de la JVM (prio)
- La priorité du thread de la JVM au sein de l'OS (os_prio)
- L'adresse du thread (tid) : ce n'est pas vraiment un ID mais plutôt un pointeur vers le thread natif JNI correspondant au thread de la JVM
- Un ID unique fourni par l'OS (Native ID - nid)
- L'état du thread
- La pile d'éxécution qui indique précisemment ce que le thread était en train d'effectuer au moment du dump
- Les objets utilisés pour réaliser des synchronisations tels que des verrous (Lock ownable synchronizers)
"Reference Handler" #8 [31747] daemon prio=10 os_prio=31 cpu=1.03ms elapsed=63.48s tid=0x000000013d809200 nid=31747 waiting on condition [0x000000016ee6a000]
java.lang.Thread.State: RUNNABLE
at java.lang.ref.Reference.waitForReferencePendingList(java.base@20.0.1/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base@20.0.1/Reference.java:246)
at java.lang.ref.Reference$ReferenceHandler.run(java.base@20.0.1/Reference.java:208)
Locked ownable synchronizers:
- NonePour finir, on trouve les informations relatives aux threads internes à la JVM ainsi que les références globales JNI (objets qui ne sont pas traités automatiquement par le garbage collector):
"VM Thread" os_prio=31 cpu=110.26ms elapsed=63.48s tid=0x000000013d7096a0 nid=17155 runnable
"GC Thread#0" os_prio=31 cpu=4.83ms elapsed=63.49s tid=0x000000013d7068c0 nid=12035 runnable
"GC Thread#1" os_prio=31 cpu=7.16ms elapsed=63.16s tid=0x000000013d71bdd0 nid=29443 runnable
"GC Thread#2" os_prio=31 cpu=7.04ms elapsed=63.16s tid=0x0000000102e0a040 nid=25603 runnable
"GC Thread#3" os_prio=31 cpu=7.34ms elapsed=63.16s tid=0x0000000102e0aae0 nid=28931 runnable
"GC Thread#4" os_prio=31 cpu=4.83ms elapsed=63.16s tid=0x0000000102e0b370 nid=26371 runnable
"GC Thread#5" os_prio=31 cpu=6.55ms elapsed=63.16s tid=0x0000000102e0bc00 nid=28675 runnable
"GC Thread#6" os_prio=31 cpu=3.62ms elapsed=62.78s tid=0x000000013d730310 nid=26891 runnable
"GC Thread#7" os_prio=31 cpu=2.98ms elapsed=62.78s tid=0x000000013d7306e0 nid=28163 runnable
"G1 Main Marker" os_prio=31 cpu=0.12ms elapsed=63.49s tid=0x000000012d6042b0 nid=13571 runnable
"G1 Conc#0" os_prio=31 cpu=2.10ms elapsed=63.49s tid=0x000000012d604b50 nid=12803 runnable
"G1 Conc#1" os_prio=31 cpu=2.58ms elapsed=62.61s tid=0x000000013d73bfe0 nid=27651 runnable
"G1 Refine#0" os_prio=31 cpu=0.02ms elapsed=63.49s tid=0x000000012d6069e0 nid=16387 runnable
"G1 Service" os_prio=31 cpu=1.83ms elapsed=63.49s tid=0x000000012d6072d0 nid=21507 runnable
"VM Periodic Task Thread" os_prio=31 cpu=37.81ms elapsed=63.42s tid=0x000000013e008a80 nid=29699 waiting on condition
JNI global refs: 15, weak refs: 0Et notre coupable parfait? #
Au sein de ces threads, celui qui est en train de répondre à notre requête ressemble à ceci:
"http-nio-8081-exec-1" #36 [33027] daemon prio=5 os_prio=31 cpu=33.02ms elapsed=62.36s tid=0x000000013daada00 nid=33027 waiting on condition [0x0000000171b70000]
java.lang.Thread.State:
at java.lang.Thread.sleep0(java.base@20.0.1/Native Method)
at java.lang.Thread.sleep(java.base@20.0.1/Thread.java:484)
at org.dlemontagner.demo.ThreaddumpApplication$BusinessService.doSlowBusiness(ThreaddumpApplication.java:43)
at org.dlemontagner.demo.ThreaddumpApplication$DemoHttpController.business(ThreaddumpApplication.java:30)
at java.lang.invoke.DirectMethodHandle$Holder.invokeVirtual(java.base@20.0.1/DirectMethodHandle$Holder)Ainsi, on peut lire que le thread est en attente (TIMED_WAITING) suite à l'excution de la méthode Java sleep par la méthode doSlowBusiness, située ligne 43 du fichier source ThreaddumpApplication.java, au sein de la classe ThreaddumpApplication$BusinessService du package org.dlemontagner.demo.
Avec cet exemple, nous connaissons déjà le point de blocage que nous recherchons. Alors comment procéder lorsqu'on ne connait pas encore le coupable?
Analyse de thread dumps #
Une technique courante pour diagnostiquer des lenteurs sur un environnement de production est de lancer plusieurs thread dumps espacés de quelques millisecondes pendant 2 à 5 secondes et d'identifier les méthodes qui sont présentes dans plusieurs de ces dumps. En effet, si la méthode est présente dans plusieurs dumps et que le thread l'exécutant est toujours le même, alors son temps d'exécution est long.
A noter que si le thread l'exécutant est différent, il peut tout de même être intéressant de s'y attarder. En effet, ceci signifie que cette méthode a statistiquement davantage d'impacts que les autres sur le temps d'exécution globale de l'application.
Il fut un temps où la recherche de ces patterns au sein des thread dumps était réalisée à grand coup de grep, sort & uniq 😱😉 Mais il existe désormais plusieurs outils permettant d'avoir une synthèse visuelle facilitant ce travail.
Ma recommandation est de se tourner vers jstack-review qui a l'avantage de pouvoir être exécuté sur le poste local et qui n'exporte aucune donnée vers des services extérieurs. Il s'agit d'une simple page html couplée à du Javascript exécuté en local et parsant les threads dumps pour produire la synthèse.
Si je reprends notre exemple, et que j'exécute plusieurs thread dumps puis que je fais traiter le fichier de logs par jstack-review, je verrai assez vite apparaitre mon coupable en parcourant la synthèse des threads:
Conclusion #
Comme vous pouvez le constater, le thread dump permet rapidement d'identifier ce que fait la JVM à un instant T.
Grace à cet outil, il est possible d'identifier la ou les méthodes entrainant une lenteur en cours d'analyse. Ainsi, l'analyse pourra se concentrer sur l'étude de cette méthode pour avancer dans la compréhension du phénomène.
Ceci reste toutefois une technique très artisanale mais qui peut s'avérer efficace en premier secours lorsque l'environnement technique auquel on fait face ne dispose pas d'autres outils.