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.