Monitoring, débogage et diagnostic de problèmes dans une JVM avec Arthas
Alibaba propose en open-source un outil nommé Arthas qui permet d’Analyser des applications Java à la volée afin d’identifier des problèmes lors de leur exécution.
Il offre des fonctionnalités comme la surveillance des statistiques d’invocations, la recherche de classes et de méthodes dans les classloaders, l’affichage des détails d’invocation de méthodes (comme les paramètres et la valeur de retour), l’affichage de la trace de la pile d’une invocation de méthode, la surveillance des métriques système et d’autres, ….
Le site web official d’Arthas est à l’url : https://alibaba.github.io/arthas/en/
Cet article fait un petit tour d’horizon de quelques unes des principales fonctionnalités proposées par Arthas.
Téléchargement et installation
Le téléchargement et l’installation d’Arthas peut se faire de plusieurs manières mais la plus simple est de télécharger le fichier artha-boot.jar.
C:\java>curl https://alibaba.github.io/arthas/arthas-boot.jar --output arthas-boot.jarArthas propose un CLI qui permet de saisir des commandes en fonction de ses besoins.
Pour lancer Arthas, il suffit d’exécuter le fichier arthas-boot.jar qui se charge de télécharger les fichiers requis et d’exécuter Arthas.
C:\java>java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.1.7
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 1400 com.oxiane.app.Main
[2]: 22396Arthas détecte les JVM exécutées en local et propose de choisir celle avec laquelle il doit interagir.
Il suffit de saisir l’identifiant concernée et d’appuyer sur « Entrée ».
C:\java>java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.1.7
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 1400 com.oxiane.app.Main
[2]: 22396
1
[INFO] arthas home: C:\Users\jm\.arthas\lib\3.1.7\arthas
[INFO] Try to attach process 1400
[INFO] Attach process 1400 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version 3.1.7
pid 1400
time 2020-01-20 10:39:14
[arthas@1400]$Une fois la connexion établie et les différentes fonctionnalités mises en place dans la JVM, Arthas affiche un prompt sous la forme [arthas@pid_jvm]$. Parmi ces fonctionnalités, il y a un serveur avec lequel le CLI va communiquer.
Le CLI offre une auto-completion en utilisant la touche tab sur le nom des commandes, les options ainsi que sur les noms de classes et de méthodes.
Pour obtenir la liste des commandes utilisables, il faut utiliser la commande help.
Pour obtenir l’aide en ligne d’une commande, il suffit d’invoquer la commande avec l’option -h.
[arthas@1400]$ cat -h
USAGE:
cat [--encoding ] [-h] files...
SUMMARY:
Concatenate and print files
OPTIONS:
--encoding File encoding
-h, --help this help
files
[arthas@1400]$
L’obtention d’informations de la JVM
Arthas propose plusieurs commandes qui permettent d’obtenir des informations de la JVM.
La commande dashboard affiche un tableau de bord rafraîchi périodiquement contenant des informations sur les threads, la mémoire, le GC et l’environnement d’exécution.
La commande heapdump permet de demander la création d’un dump de la mémoire heap dans un fichier binaire au format hprof.
La commande thread permet d’obtenir des informations sur les threads.
Il est possible d’obtenir la stacktrace d’un thread en passant son id en paramètre de la commande thread.
[arthas@1400]$ thread 10
"Service_1" Id=10 TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Unknown Source)
at java.util.concurrent.TimeUnit.sleep(Unknown Source)
at com.oxiane.app.Service.traiter(Service.java:12)
at com.oxiane.app.ThreadService.run(ThreadService.java:18)
Affect(row-cnt:0) cost in 13 ms.
[arthas@1400]$La commande jvm affiche des informations sur la JVM : les variables d’environnement, le classpath, le librarypath, la mémoire, le nombre de threads, les GC, le nombre de classes chargées, …
La commande sysprop permet d’afficher et de modifier des propriétés systèmes de la JVM.
La commande sysenv affiche les variables d’environnement système.
La commande vmoption permet d’afficher et de modifier les options de diagnostic de la JVM.
Il est alors très facile de changer la valeur d’une propriété pour par exemple activer les traces de l’activité du GC.
[arthas@1400]$ vmoption PrintGC true
Successfully updated the vm option.
PrintGC=true
[arthas@1400]$Une fois la commande exécutée, les traces sont consultables dans la console de sortie de la JVM.
[GC (Allocation Failure) 46321K->22289K(112128K), 0.0024506 secs]
[GC (Allocation Failure) 46353K->22225K(112128K), 0.0011319 secs]
[GC (Allocation Failure) 46289K->22257K(112128K), 0.0007702 secs]
Les fonctionnalités de profiling
La commande monitor affiche périodiquement des statistiques sur l’exécution d’une méthode.
[arthas@1400]$ monitor com.oxiane.app.Service traiter -c 20
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 13 ms.
timestamp class method total success fail avg-rt(ms) fail-rate
---------------------------------------------------------------------------------------------------
2020-01-20 14:30:02 com.oxiane.app.Service traiter 7 7 0 2044,41 0,00%
timestamp class method total success fail avg-rt(ms) fail-rate
---------------------------------------------------------------------------------------------------
2020-01-20 14:30:22 com.oxiane.app.Service traiter 5 5 0 1847,29 0,00%
[arthas@1400]$La commande stack affiche la pile d’appel lors de l’invocation d’une méthode.
[arthas@1400]$ stack com.oxiane.app.Compteur
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:2) cost in 15 ms.
ts=2020-01-20 14:32:16;thread_name=Service_2;id=b;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@73d16e93
@com.oxiane.app.Service.traiter()
at com.oxiane.app.ThreadService.run(ThreadService.java:18)
ts=2020-01-20 14:32:19;thread_name=Service_1;id=a;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@73d16e93
@com.oxiane.app.Service.traiter()
at com.oxiane.app.ThreadService.run(ThreadService.java:18)
[arthas@1400]$La commande trace permet de tracer le temps d’exécution des méthodes de la pile d’invocation.
[arthas@1400]$ trace com.oxiane.app.Service traiter
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 18 ms.
`---ts=2020-01-20 14:35:02;thread_name=Service_1;id=a;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@73d16e93
`---[3043.1976ms] com.oxiane.app.Service:traiter()
`---[0.0348ms] com.oxiane.app.Compteur:incrementer() #11
`---ts=2020-01-20 14:35:08;thread_name=Service_2;id=b;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@73d16e93
`---[1050.7912ms] com.oxiane.app.Service:traiter()
`---[0.0471ms] com.oxiane.app.Compteur:incrementer() #11
[arthas@1400]$Cela permet de connaitre le temps d’exécution des différentes méthodes invoquées.
La commande watch permet de visualiser les paramètres, la valeur de retour et les exceptions levées lors de l’invocation de méthodes.
[arthas@1400]$ watch com.oxiane.app.Service traiter "{params,returnObj}"
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 17 ms.
ts=2020-01-20 14:39:58; [cost=58.3404ms] result=@ArrayList[
@Object[][isEmpty=true;size=0],
@Integer[4991],
]
ts=2020-01-20 14:40:04; [cost=1049.1759ms] result=@ArrayList[
@Object[][isEmpty=true;size=0],
@Integer[4992],
]
[arthas@1400]$La commande tt permet d’afficher toutes les invocations d’une méthode.
[arthas@1400]$ tt com.oxiane.app.Compteur incrementer -t
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 12 ms.
INDEX TIMESTAMP COST(m IS-RE IS-EX OBJECT CLASS METHOD
s) T P
-------------------------------------------------------------------------------------------------------------- 1000 2020-01-20 14:4 0.1106 true false 0x5f11d00b Compteur incrementer
3:05
1001 2020-01-20 14:4 0.0339 true false 0x5f11d00b Compteur incrementer
3:13
1002 2020-01-20 14:4 0.0268 true false 0x5f11d00b Compteur incrementer
3:15
[arthas@1400]$Attention : les commandes monitor, watch, trace et tt injectent du bytecode dans les classes concernées. Si l’application est en production ou doit continuer à être exécutée, il ne faut pas oublier d’invoquer la commande stop ou reset dans la CLI lorsque l’on a terminé les activités avec Arthas.
Les fonctionnalités relatives aux classes et aux classloaders
La commande sc permet de rechercher les classes chargées dans la JVM.
[arthas@1400]$ sc com.oxiane.app.*
com.oxiane.app.Compteur
com.oxiane.app.Main
com.oxiane.app.Main$1
com.oxiane.app.Service
com.oxiane.app.ThreadService
Affect(row-cnt:5) cost in 8 ms.
[arthas@1400]$L’option -d de la commande sc permet d’obtenir des informations sur une classe. L’option -f affiche les champs.
[arthas@1400]$ sc -df com.oxiane.app.Main
class-info com.oxiane.app.Main
code-source /C:/java/workspace-2018-12-Test/Arthas-demo-oxiane/bin/
name com.oxiane.app.Main
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name Main
modifier public
annotation
interfaces
super-class +-java.lang.Object
class-loader +-sun.misc.Launcher$AppClassLoader@73d16e93
+-sun.misc.Launcher$ExtClassLoader@2f5fd2cb
classLoaderHash 73d16e93
fields name valeur
type int
modifier public,static
value 1234
Affect(row-cnt:1) cost in 5 ms.
[arthas@1400]$La commande getstatic permet d’afficher la valeur d’une propriété static.
[arthas@1400]$ getstatic com.oxiane.app.Main valeur
field: valeur
@Integer[1234]
Affect(row-cnt:1) cost in 4 ms.
[arthas@1400]$La commande sm permet de rechercher des méthodes dans les classes chargées de la JVM.
[arthas@1400]$ sm com.oxiane.app.Service
com.oxiane.app.Service ()V
com.oxiane.app.Service traiter()I
Affect(row-cnt:2) cost in 8 ms.
[arthas@1400]$ sm -d com.oxiane.app.Service traiter
declaring-class com.oxiane.app.Service
method-name traiter
modifier public,static
annotation
parameters
return int
exceptions java.lang.InterruptedException
classLoaderHash 73d16e93
Affect(row-cnt:1) cost in 6 ms.
[arthas@1400]$La commande classloader permet d’afficher les classloaders.
La commande jad permet de décompiler une classe chargée dans la JVM.
[arthas@1400]$ jad com.oxiane.app.Compteur
ClassLoader:
+-sun.misc.Launcher$AppClassLoader@73d16e93
+-sun.misc.Launcher$ExtClassLoader@2f5fd2cb
Location:
/C:/java/workspace-2018-12-Test/Arthas-demo-oxiane/bin/
/*
* Decompiled with CFR.
*/
package com.oxiane.app;
import java.util.concurrent.atomic.AtomicInteger;
public class Compteur {
private static AtomicInteger valeur = new AtomicInteger(0);
public int incrementer() {
return valeur.incrementAndGet();
}
}
Affect(row-cnt:1) cost in 115 ms.
[arthas@1400]$La commande mc permet de compiler un fichier source Java. Pour pouvoir être utilisée, l’application doit être exécutée avec un JDK mais pas avec un JRE.
La commande redefine permet de charger et remplacer à chaud le bytecode d’une classe. Un exemple de mise en oeuvre est détaillé dans la section suivante.
Exemple d’utilisation : décompilation et modification à chaud d’une classe
Dans cette section, une classe chargée dans la JVM va être décompilée, modifiée pour afficher une trace d’exécution dans la sortie standard, compilée et rechargée à chaud dans la JVM.
La première étape consiste à rechercher la classe pour obtenir son classloader.
[arthas@1400]$ sc -d com.oxiane.app.Compteur
class-info com.oxiane.app.Compteur
code-source /C:/java/workspace-2018-12-Test/Arthas-demo-oxiane/bin/
name com.oxiane.app.Compteur
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name Compteur
modifier public
annotation
interfaces
super-class +-java.lang.Object
class-loader +-sun.misc.Launcher$AppClassLoader@73d16e93
+-sun.misc.Launcher$ExtClassLoader@2f5fd2cb
classLoaderHash 73d16e93
Affect(row-cnt:1) cost in 6 ms.
[arthas@1400]$Il faut utiliser la commande jad pour décompiler le bytecode de la classe dans un fichier.
[arthas@1400]$ jad --source-only com.oxiane.app.Compteur > c:/temp/Compteur.java
[arthas@1400]$ cat c:/temp/Compteur.java
/*
* Decompiled with CFR.
*/
package com.oxiane.app;
import java.util.concurrent.atomic.AtomicInteger;
public class Compteur {
private static AtomicInteger valeur = new AtomicInteger(0);
public int incrementer() {
return valeur.incrementAndGet();
}
}
[arthas@1400]$Modifier la méthode incrementer() de la classe Compteur pour ajouter un message dans la sortie standard.
[arthas@1400]$ cat c:/temp/Compteur.java
/*
* Decompiled with CFR.
*/
package com.oxiane.app;
import java.util.concurrent.atomic.AtomicInteger;
public class Compteur {
private static AtomicInteger valeur = new AtomicInteger(0);
public int incrementer() {
System.out.println("Invocation methode incrementer");
return valeur.incrementAndGet();
}
}
[arthas@1400]$Attention : il n’est pas possible d’ajouter de membres (propriétés ou méthodes) dans la classe.
Utiliser la commande mc pour compiler la classe modifée.
[arthas@1400]$ mc -d c:/temp c:/temp/Compteur.java
Memory compiler output:
c:\temp\com\oxiane\app\Compteur.class
Affect(row-cnt:1) cost in 317 ms.
[arthas@1400]$La dernière étape consiste à utiliser la commande redefine pour remplacer à chaud le bytecode chargé de la classe dans la JVM par celui recompilé.
[arthas@1400]$ redefine -c 55f96302 c:/temp/com/oxiane/app/Compteur.class
redefine success, size: 1
[arthas@1400]$Il est alors possible consulter la sortie standard de l’application pour consulter les traces ajoutées.
Service_1 : 134
Service_2 : 135
Service_1 : 136
Service_1 : 137
Service_2 : 138
[GC (Allocation Failure) 113384K->25335K(173056K), 0.0018479 secs]
Service_1 : 139
Service_2 : 140
Invocation methode incrementer
[GC (Allocation Failure) 100095K->25351K(160256K), 0.0020078 secs]
Service_1 : 141
Invocation methode incrementer
Service_2 : 142
Invocation methode incrementer
Service_2 : 143
Invocation methode incrementer
Invocation methode incrementer
Service_2 : 144
[GC (Allocation Failure) 97543K->25351K(162816K), 0.0020652 secs]
Service_1 : 145
Invocation methode incrementerAttention : les commandes stop ou reset ne changent pas le bytecode rechargé à chaud. Pour revenir en arrière, la seule solution est de recharger à chaud le bytecode précédemment chargé par la JVM.
Quitter et arrêter Arthas
Pour quitter le CLI, il faut utiliser la commande quit ou exit qui interrompt la communication avec le serveur démarré dans la JVM.
Attention, ces deux commandes ne terminent pas l’exécution du serveur démarré dans la JVM. Pour cela, il faut utiliser les commandes stop ou shutdown. Il est important d’invoquer une de ces deux commandes notamment en production afin de ne pas dégrader les performances de la JVM.
Conclusion
Arthas est un outil pratique notamment car il est open-source et surtout il permet d’obtenir de nombreuses informations pour identifier des problèmes lors de l’exécution d’une application dans la JVM. Son utilisation via le CLI n’impliquant pas de redémarrer la JVM, il peut être pratique dans de nombreuses situations même éventuellement en production.
