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.jar

Arthas 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]: 22396

Arthas 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.

dashboard arthas

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.

threads arthas

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.

options jvm arthas

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 incrementer

Attention : 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.