BT

Diffuser les Connaissances et l'Innovation dans le Développement Logiciel d'Entreprise

Contribuez

Sujets

Sélectionner votre région

Accueil InfoQ Articles Tout sur la JVM sans jamais avoir osé lui demander en ligne de commande

Tout sur la JVM sans jamais avoir osé lui demander en ligne de commande

Les développeurs connaîssent généralement (ou devraient connaître !) les outils graphiques fournis avec le JDK permettant de collecter des informations concernant le comportement et la configuration des machines virtuelles en cours d'exécution. On pourra citer notamment la jconsole: elle est vieille et elle est moche, mais elle fournit moultes informations et surtout une interface permettant d'interagir avec les composants logiciels exposés via l'interface JMX. Java6 a apporté un peu de modernité en intégrant VisualVM. Au delà d'être nettement plus sexy que la jconsole, elle marque une rupture sur deux points : premièrement, son architecture extensible permet d'ajouter des plugins - d'ailleurs si vous ne l'avez pas déjà fait, je vous recommande l'excellent VisualGC disponible sur le VisualVM Plugins Center ; mais le point le plus important à mon sens est qu'un profiler est maintenant fourni avec le JDK. Enfin, depuis peu, nous pouvons utiliser Java Mission Control qui est un utilitaire issu de la synergie entre Hotspot et JRockit.

Or, ce ne sont pas ces outils qui vont être mis en exergue dans cet article. Ici il va être question de terminal et de ligne de commande ! Pourquoi se concentrer sur cette interface austère en 2014 ? Tout d'abord, car la plupart des développeurs sont amenés régulièrement à se connecter sur des serveurs qui sont purement et simplement dépourvus d'interface graphique. Ensuite, les modalités d'utilisation sont on ne peut plus simples : pas besoin de négocier une ouverture de port spécifique, une connexion à distance (ssh) et l'accès au JDK suffisent. Notons que la plupart des interactions sont sans impact sensible sur le comportement des applications. Enfin, les outils en ligne de commande permettent aisément d'automatiser des tâches dans des scripts.

Les commandes présentées sont celles fournies pour la JVM Hotspot (Oracle).

jps

jps n'est autre que l'alter ego du vénérable ps, mais il est dédié aux JVM. Deux avantages principaux par rapport à son ancêtre : il nous épargne le sempiternel | grep java à chaîner au ps, de plus il est de facto également disponible sur la plateforme Windows.

L'affichage par défaut de jps se présente sur deux colonnes présentant respectivement l'identifiant de processus et le nom de l'application :

$ jps
7502 ApacheJMeter.jar
8097 Bootstrap
8110 Jps

jps est elle-même une application Java, expliquant qu'elle se retrouve listée.

jps -l permet d'afficher le nom complètement qualifié de la classe de démarrage de l'application :

$ jps -l
8117 sun.tools.jps.Jps
7502 /Applications/apache-jmeter-2.10/bin/ApacheJMeter.jar
8097 org.apache.catalina.startup.Bootstrap

Nous pouvons maintenant déduire qu'un injecteur JMeter et un conteneur Tomcat sont en cours d'exécution sur cette machine.

jps -v affiche tous les arguments passés au démarrage de la JVM :

$ jps -v
7502 ApacheJMeter.jar
8097 Bootstrap -Djava.util.logging.config.file=/opt/apache-tomcat-7.0.54/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/opt/apache-tomcat-7.0.54/endorsed -Dcatalina.base=/opt/apache-tomcat-7.0.54 -Dcatalina.home=/opt/apache-tomcat-7.0.54 -Djava.io.tmpdir=/opt/apache-tomcat-7.0.54/temp
8171 Jps -Dapplication.home=/Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home -Xms8m

C'est le conteneur Tomcat qui va être l'objet de toutes les attentions.

jinfo

jinfo affiche la configuration de la JVM, c'est-à-dire l'intégralité des propriétés systèmes (par défaut ainsi que celles définies au démarrage grâce aux commutateurs -D) ainsi que les paramètres de démarrage de la JVM :

$ jinfo 8097
Attaching to process ID 8097, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.45-b08
Java System Properties:

jboss.i18n.generate-proxies = true
java.runtime.name = Java(TM) SE Runtime Environment
java.vm.version = 24.45-b08
sun.boot.library.path = /Library/Java/JavaVirtualMachines/jdk1.7.0_45.jdk/Contents/Home/jre/lib
shared.loader =
gopherProxySet = false
java.vendor.url = http://java.oracle.com/
java.vm.vendor = Oracle Corporation

[...]

VM Flags:

-Djava.util.logging.config.file=/opt/apache-tomcat-7.0.54/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/opt/apache-tomcat-7.0.54/endorsed -Dcatalina.base=/opt/apache-tomcat-7.0.54 -Dcatalina.home=/opt/apache-tomcat-7.0.54 -Djava.io.tmpdir=/opt/apache-tomcat-7.0.54/temp

L'affichage peut être contraint aux seules propriétés systèmes via jinfo -sysprops ou aux paramètres de démarrage avec jinfo -flags. Notez que ces derniers paramètres peuvent peuvent être retrouvés par deux commandes, jps et jinfo, ce type de chevauchement se retrouve dans plusieurs commandes.

jstack

jstack est une commande qui propose les données portant sur l'intégralité des threads présents dans la JVM. L'affichage fournit leur état, la pile d'appels complète ainsi que les moniteurs sur lesquels ils sont susceptibles d'être synchronisés ou en attente. C'est ce qu'on appelle un thread dump.

$ jstack 8097
2014-07-12 12:02:11
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.45-b08 mixed mode):

"http-bio-8080-exec-9" daemon prio=5 tid=0x00007f984f69d000 nid=0x8503 waiting on condition [0x000000011ba75000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000007e9c96130> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104)
    at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:744)

[...]

"http-bio-8080-exec-170" daemon prio=5 tid=0x00007f984e012800 nid=0xf407 waiting for monitor entry [0x0000000119e4a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1605)
    - waiting to lock <0x00000007807f3518> (a org.apache.catalina.loader.WebappClassLoader)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1571)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:207)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:138)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:113)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:105)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:57)
    at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:147)
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:124)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.error(Logger.java:555)
    at org.blep.aop.logging.LoggingAspect.logAfterThrowing(LoggingAspect.java:26)
    at sun.reflec ...

[...]

"http-bio-8080-exec-175" daemon prio=5 tid=0x00007f984a397000 nid=0xb00f runnable [0x000000011aa87000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Throwable.fillInStackTrace(Native Method)
    at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
    - locked <0x00000007f6790ac0> (a java.security.PrivilegedActionException)
    at java.lang.Throwable.<init>(Throwable.java:310)
    at java.lang.Exception.<init>(Exception.java:102)
    at java.security.PrivilegedActionException.<init>(PrivilegedActionException.java:66)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:425)
    - locked <0x00000007805e08b8> (a org.apache.catalina.loader.StandardClassLoader)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:270)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1707)
    - locked <0x00000007807f3518> (a org.apache.catalina.loader.WebappClassLoader)
    at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1571)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:207)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:138)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:113)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:105)
    at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:57)
    at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:147)
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:124)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.error(Logger.java:555)
    at org.blep.aop.logging.LoggingAspect.logAfterThrowing(LoggingAspect.java:26)
    at sun.reflect.Ge ...

Dans cet extrait, dont les piles d'appels sont incomplètes pour des raisons de lisibilité, il peut être constaté que le thread http-bio-8080-exec-9 est en attente dans la file du pool de threads du connecteur HTTP, tandis que http-bio-8080-exec-170 attend de pouvoir acquérir le moniteur 0x00000007807f3518 détenu par http-bio-8080-exec-175. Ces informations sont donc fondamentales pour débusquer les verrous sujets à compétitions intenses entre les threads, mais également des latences sur les entrées/sorties, voire obtenir des pistes d'investigation lors d'une recherche de causes de consommation CPU.

jmap

jmap permet d'obtenir des informations sur la mémoire dont voici quelques uns des usages les plus utiles.

jmap -heap affiche le plan mémoire de la JVM observée :

$ jmap -heap 8097
Attaching to process ID 8097, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.45-b08

using thread-local object allocation.
Parallel GC with 8 thread(s)

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 2147483648 (2048.0MB)
   NewSize          = 1310720 (1.25MB)
   MaxNewSize       = 17592186044415 MB
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 21757952 (20.75MB)
   MaxPermSize      = 85983232 (82.0MB)
   G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 706740224 (674.0MB)
   used     = 502988608 (479.68731689453125MB)
   free     = 203751616 (194.31268310546875MB)
   71.17022505853579% used
From Space:
   capacity = 4194304 (4.0MB)
   used     = 3922272 (3.740570068359375MB)
   free     = 272032 (0.259429931640625MB)
   93.51425170898438% used
To Space:
   capacity = 4718592 (4.5MB)
   used     = 0 (0.0MB)
   free     = 4718592 (4.5MB)
   0.0% used
PS Old Generation
   capacity = 127401984 (121.5MB)
   used     = 72526992 (69.16712951660156MB)
   free     = 54874992 (52.33287048339844MB)
   56.92767861448688% used
PS Perm Generation
   capacity = 85983232 (82.0MB)
   used     = 67951024 (64.80314636230469MB)
   free     = 18032208 (17.196853637695312MB)
   79.02822727110328% used

27088 interned Strings occupying 3234576 bytes.

Le principal intérêt est la possibilité d'obtenir une vision claire de la configuration de chacune des zones du tas et de connaître leur taux de saturation.

jmap -histo donne la liste de toutes les classes chargées, le nombre d'instances et l'occupation mémoire de chacune des instances. Notez que cette valeur ne prend pas en compte l'occupation des objets potentiellement référencés à l'intérieur de chaque instance.

$ jmap -histo 8097

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1649024      341201712  [C
   2:        395505       82392208  [B
   3:        129996       27709552  [I
   4:        349629       25028872  [Ljava.lang.Object;
   5:        876689       21040536  java.lang.String
   6:        118981       16283528  <constMethodKlass>
   7:        118981       15238992  <methodKlass>
   8:         11812       13006112  <constantPoolKlass>
   9:        122953        9407368  [S
  10:         11806        8479304  <instanceKlassKlass>
  11:          9361        6948736  <constantPoolCacheKlass>
  12:        189437        6061984  java.lang.StackTraceElement
  13:        120131        4805240  java.util.LinkedHashMap$Entry
  14:        108991        3487712  java.util.HashMap$Entry
  15:         53331        3413184  java.util.regex.Matcher

jmap -dump permet de déverser l'intégralité du contenu de la mémoire de la JVM dans un fichier, c'est ce qu'on appelle un heap dump :

$ jmap -dump:file=/tmp/heap.hprof,format=b,live 8097
Dumping heap to /private/tmp/heap.hprof ...
Heap dump file created

$ ls -lh /tmp/heap.hprof
-rw-------  1 blep  wheel    79M 13 jul 10:21 /tmp/heap.hprof

Ici, la clause live indique que seuls les objets référencés (c'est à dire non collectables) sont attendus, impliquant un full GC avant l'opération. La taille du fichier généré est donc naturellement égale à l'occupation mémoire, c'est une donnée à prendre en considération lors du choix de la destination pour éviter la saturation d'une partition si la JVM exploite un tas de taille importante.

Le fichier doit ensuite être exploité avec un outil de profiling comme Memory Analyzer Tool (aka MAT), VisualVM ou des profilers commerciaux comme JProfiler.

L'analyse du heap lump donne des informations de première importance, car grâce à elle, il est possible de connaître la taille et le contenu de chaque objet. Et cette fois il est question de la taille de la grappe, la retained size, c'est à dire la quantité de mémoire qui serait libérée si l'instance devait être collectée. C'est une information déterminante pour diagnostiquer les causes d'une OutOfMemoryError ou encore pour effectuer une projection des besoins en mémoire d'une application lorsqu'elle sera soumise à une sollicitation importante : par exemple, on peut facilement déterminer l'occupation des sessions HTTP et dimensionner la JVM au regard de la charge attendue.

jstat

jstat donne de nombreuses statistiques sous différents formats concernant le comportement de la JVM sur des aspects aussi variés que l'état de la mémoire et l'activité du GC ou du JIT.

$ jstat -gcutil 8097 1s
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
  0,00  76,07  21,27  47,87  79,03    505    2,526     3    0,718    3,244
 81,91   0,00  19,12  47,93  79,03    506    2,530     3    0,718    3,248
  0,00  82,65  11,42  47,98  79,03    507    2,534     3    0,718    3,252
 81,26   0,00  10,69  48,03  79,03    508    2,539     3    0,718    3,257
  0,00  81,64   8,68  48,09  79,03    509    2,543     3    0,718    3,261
 85,37   0,00   6,78  48,14  79,03    510    2,547     3    0,718    3,266
  0,00  87,79   0,00  48,19  79,03    511    2,552     3    0,718    3,270
  0,00  87,79  97,81  48,19  79,03    512    2,552     3    0,718    3,270

Ci-dessus, il est demandé à jstat de produire un affichage continu rafraîchi toutes les secondes rapportant l'état de la mémoire et l'activité du GC : les 5 premières colonnes donnent le taux de saturation, en pourcentage, des différents pools (S0/1: les deux zones d'échange de la survivor, E: l'Eden, O: la old generation et P pour la permanent generation) ; les colonnes suivantes portent sur le garbage collecter: YGC pour le nombre de minore collections, YGCT pour leur durée cumulée en millisecondes, la même chose pour les full GC sur les FGC et FGCT et enfin le temps total cumulé de nettoyage dans GCT. Dans le cas présenté, l'échange entre les deux zones de la survivor à chaque ramassage est clairement illustré.

L'activité du JIT peut être suivie avec jstat -printcompilation:

$ jstat -printcompilation 8097 1s
Compiled  Size  Type Method
    4429    111    1 org/h2/expression/Parameter isEverything
    4507     11    1 org/joda/time/base/AbstractDateTime <init>
    4548    225    1 org/h2/value/ValueDate fromDateValue
    4561    697    1 org/h2/util/DateTimeUtils dateValueFromDate
    4574      6    1 org/springframework/security/core/context/SecurityContextImpl <init>
    4589     84    1 org/springframework/web/servlet/mvc/condition/ConsumesRequestCondition compareTo
    4604     12    1 com/fasterxml/jackson/core/JsonFactory$Feature getMask
    4621     95    1 java/util/Arrays$ArrayList contains
    4647     17    1 org/springframework/web/servlet/resource/ResourceHttpRequestHandler writeContent

En substance, un échantillon des méthodes optimisées par le compilateur apporte des informations rarement exploitables. En revanche, si l'affichage est stabilisé, c'est-à-dire que peu de méthodes sont retravaillées pendant la période observée, cela autorise à déduire que l'activité du compilateur est limitée. Ce constat, entre autres, peut contribuer à valider des mesures de temps d'exécution car le code exécuté est chaud et le travail du JIT ne rentre pas (ou peu) en compétition avec l'application dans la file d'attente du processeur.

Cet article présente quelques unes des commandes et leurs options qui me paraîssent les plus utiles, mais n'hésitez pas à fouiner dans le répertoire bin du JDK et à consulter la documentation !

Au sujet de l'Auteur

Brice Leporini est un développeur sénior qui totalise plus de quinze ans d’expérience sur différentes technologies dont dix focalisées sur l’ecosystème Java et les architectures n-tiers. Freelance depuis huit ans, son activité actuelle oscille entre le coaching technique d’équipes de jeunes geeks, les travaux d’amélioration de performance et les études préalables. Retrouvez-le sur Twitter à @blep.

Evaluer cet article

Pertinence
Style

Contenu Éducatif

BT