Introduction
La JVM est un système complexe (JIT, GC, ...), pouvant être optimisé dans son utilisation. Il faut cependant faire attention à ne pas optimiser trop tôt car ce faisant on spécialise son utilisation et si cela répond bien aux use cases d'aujourd'hui, rien ne garantie que cela ne dégradera pas les performances pour les use cases de demain. Quoi qu'il en soit l'optimisation passe par de l'observation et des tests pour étudier les impacts. Et bien souvent les settings de base suffisent.
A savoir la JVM via JIT est un système intelligent qui s'optimise (et se désoptimise) lui même à la volée (paramétrable également par jvm argument). Conclusion on peut observer un comportement localement qui ne sera pas le comportement une fois en production si l'on a pas pris les bonnes précautions.
De même faire attention à l'implémentation de la JVM utilisée, les trois principalement rencontrées sont :
- Hotspot d'Oracle (anciennement Sun)
- JRockit d'Oracle (anciennement BEA), on la trouve sur serveurs applicatifs Weblogic
- J9 d'IBM, on la trouve sur serveur applicatifs Websphere
Ces 3 JVM peuvent avoir des comportements différents, des paramètres (jvm args) différents comme pour l'activation de la compression des références d'objets pour les jvm 64bit, voir OOPS. Suite aux différents rachats Oracle possède maintenant deux de ces JVM et met en place un projet de convergence, voir les liens suivant sur le sujet :
- Oracle's JVM Strategy (Henrik Stahl, Oracle) : https://blogs.oracle.com/henrik/entry/oracles_jvm_strategy
- Oracle press : http://www.oracle.com/us/corporate/press/173782
- Article : http://www.infoworld.com/d/developer-world/oracle-moving-merge-jrockit-hotspot-jvms-448
- Presentation du JavaOne 2011 (Marcus Hirt, Oracle) : http://parleys.com/play/514892290364bc17fc56c339/chapter0/about
- Une des premieres conséquence visible de la convergence : mission control (Jdk 7u40) : http://technology.amis.nl/2013/10/06/javaone-2013-java-mission-control-2/
Une dernière JVM apparait régulièrement, beaucoup plus spécifique c'est la Zing d'Azul System (http://www.azulsystems.com/products/zing/whatisit), je ne développerais pas ici.
Dernier point les JVM, jdk sont des choses dynamiques, terrain encore en évolutions sur lesquels une communauté active et les éditeurs travaillent. Il est toujours bien de savoir sur quelle version on est, les différences qu'elles apportent, ... Quelques exemples d'évolutions récentes qui ont un impact :
- apparition nouvelle instruction bytecode (invokedynamic) avec Java7 http://www.oracle.com/technetwork/articles/javase/dyntypelang-142348.html
- disparition du permgenspace avec Java8 http://javaeesupportpatterns.blogspot.fr/2013/02/java-8-from-permgen-to-metaspace.html
- arrivé de mission controle avec Jdk7u40 dans le cadre de la convergence JRockit, Hotspot
Il existe un certain nombre de produits sur le marché (software, services) facilitant l'étude du comportement d'une JVM :
- en se basant sur les api, services de la jvm qui permettent de collecter des métriques et propose une interface pour les exploiter. La collecte des métriques est souvent réalisée par des agents développés et attachés à la jvm que l'on veut suivre, voir cet article.
- en fournissant des services interprétant les logs de GC et donnant un rendu plus visuel
- en instrumentant le code par différentes techniques (aop, introspection, ....)
Dans ce billet je ne parlerais pas de ces solutions mais il est toujours bon de savoir que cela existe, ce qu'elles permettent de faire et comment elle le font. Quelques un de ceux ci :
Les plus connu :
- Yourkit (profiling jvm) : http://www.yourkit.com/java/profiler/
- JProfiler (profiling jvm) : http://www.ej-technologies.com/products/jprofiler/overview.html
- appdynamics (monitoring) : http://www.appdynamics.fr/solutions/appdynamics-java-monitoring
- newrelic (monitoring) : http://newrelic.com/java
- JRebel (suivi et déploiement à chaud de code) : http://zeroturnaround.com/software/jrebel/
- Takipi (monitoring application) : http://www.takipi.com/
- Chrononsystems (trace et chronologie de la vie de l'application) : http://chrononsystems.com/
Des projets plus développeurs :
- De Twitter pour l'anayse Garbage Collector : https://github.com/twitter/jvmgcprof
- D'Azul system jHiccup : http://www.azulsystems.com/product/jHiccup
- Analyse GC : https://github.com/chewiebug/GCViewer
- Analyse GC : https://code.google.com/a/eclipselabs.org/p/garbagecat/
- Analyse GC : https://code.google.com/p/verbosegcanalyzer/
- Tooling JVM : https://github.com/aragozin/jvm-tools
- Tooling jvm : https://code.google.com/p/jvmtop/
Queqlues produits plus spécifique :
- HPJmeter de HP : https://h20392.www2.hp.com/portal/swdepot/displayProductInfo.do?productNumber=HPJMETER
- IBM HeapAnalyzer : https://www.ibm.com/developerworks/community/groups/service/html/communityview?communityUuid=4544bafe-c7a2-455f-9d43-eb866ea60091&open&S_TACT=105AGX59&S_CMP=GRsite-jw22
- Profiler qui date un peu : http://www.oracle.com/technetwork/articles/javase/perfanal-137231.html
Pour finir cette introduction, une url présentant une vision assez complète des JVM arguments que l'on peut utiliser : JVM Arguments card
Observation de la JVM
Dans la partie qui va suivre on va discuter d'un certain nombre de JVM arguments (flags activant certaine options, comportement, traces). Pour au démarrage de votre process java avoir connaissance des jvm args, il existe un jvm arg : -XX:+PrintFlagsFinal qui permettra d'avoir une sortie console du type
[Global flags]
...
uintx AdaptiveSizeThroughPutPolicy = 0 {product}
uintx AdaptiveTimeWeight = 25 {product}
bool AdjustConcurrency = false {product}
bool AggressiveOpts = false {product}
intx AliasLevel = 3 {product}
intx AllocateInstancePrefetchLines = 1 {product}
...
Observation via les logs
La jvm effectue un certain nombre de tâches techniques depuis son démarrage jusqu'à son arrêt. Il peut être utile pour comprendre son comportement d'avoir une visibilité concernant ces opérations. Pour ce faire il est possible d'activer des logs techniques.
Les Logs GC (Garbage Collector)
Il est recommandé de les activer systématiquement en environnement de développement, voir même en production (l'overhead reste léger, juste faire attention au volume de log généré sur le filesystem) car les informations fournies peuvent être précieuses et un évènement survenu ne sera pas toujours reproductible.
- Activation des logs Garbage collector : -XX:+PrintGC
- Activation logs détaillé : -XX:+PrintGCDetails (recommandé)
- Activation du timestamp pour savoir quand l'évènement a eu lieu : -XX:+PrintGCTimeStamps (nombre de seconde depuis le démarrage de la jvm) ou -XX:+PrintGCDateStamps (format date)
- Spécifier les fichiers de log destination : -Xloggc:<file>
A partir des jdk 1.6_34 et 1.7_2, possibilité de spécifier un roll sur les fichiers de configuration :
- Activation : -XX:+UseGCLogFileRotation
- Obligatoire en cas d'activation de la rotation, nombre de fichier à garder : -XX:NumberOfGCLogFiles=<number of files>
- Obligatoire en cas d'activation de la rotation, taille de chaque fichier (possibilité d'utiliser la notation K (Kilo), m (mega)) : -XX:GCLogFileSize=<size>
De plus -XX:+PrintGC et -XX:+PrintGCDetails sont dit "Manageable", c'est à dire qu'ils peuvent être activés runtime. Pour se faire deux manière
- via le MBean com.sun.management:type=HotSpotDiagnostic, l'operation setVMOption (les parametres sont nom et valeur, voir javadoc pour plus de détail)
- via le command line tool jinfo (fourni avec le jdk) "-flag <name>=<value> to set the named VM flag to the given value"
Ces logs permettent de savoir quand tourne le Garbage Collector, combien de temps cela dure, ce qu'il fait. Le format de logs étant standard, un certain nombre d'outils permettent d'en avoir une visualisation graphique.
Logs Classloading
Plus que pour de l'optimisation, ces logs permettent surtout de savoir quelle classe a été chargée depuis quelle librairie. Très pratique quand par dépendance transitive on tire plusieurs versions d'une même librairie (les parsers XML par exemple).
Le jvm arg est "-verbose:class" à ajouter au lancement. Il permettra d'avoir tout le class loading (classe technique, jdk, librairies utilisées) sous la forme :
...
[Loaded java.util.HashMap from shared objects file]
[Loaded sun.misc.Hashing from D:\jdk1.7.0_25\jre\lib\rt.jar]
....
[Loaded org.junit.internal.runners.model.ReflectiveCallable from file:/C:/Users/Toto/.m2/repository/junit/junit/4.11/junit-4.11.jar]
....
C'est une sortie console, on ne peut pas spécifier de fichier de sortie contrairement aux logs GC.
Logs JIT
Un autre aspect dynamique de la jvm, que l'on aborde moins souvent au quotidien et qui je pense nécessite d'être outillé pour analyser : les logs du JIT (JustInTime) qui pratique les optimisations et désoptimisation du code à la volée.
Un outil : JITWatch (https://github.com/AdoptOpenJDK/jitwatch)
Article à son sujet :
- http://commons.wikimedia.org/w/index.php?title=File%3AUnderstanding_HotSpot_Logs.pdf&page=1
- http://www.chrisnewland.com/images/jitwatch/HotSpot_Profiling_Using_JITWatch.pdf
- http://zeroturnaround.com/rebellabs/why-it-rocks-to-finally-understand-java-jit-with-jitwatch/
Observation via les dumps
Un dump est une photo à moment donné de l'état de notre JVM. Il existe principalement deux types de dump. Le heap dump qui donne le contenu de la mémoire et le thread dump qui liste les thread en vie, leur état et leur stack d'appel afin de savoir ce qu'elles sont en train de faire au moment du dump.
HeapDump
Il est possible de générer un heapdump à la demande mais également de le générer systématiquement sur un OutOfMemory. Il faut bien avoir conscience que la taille du fichier dump sera au moins égale à la taille du heap.
Jvm args pour avoir un heap dump sur les OOM :
- -XX:+HeapDumpOnOutOfMemoryError
- -XX:HeapDumpPath=<path to dump file>
- depuis Java 6, via l'appel d'un MBean : com.sun.management:type=HotSpotDiagnostic, l'operation dumpHeap (parametre sont outputfile et onlyLiveObject, voir javadoc)
- via l'outil ligne de commande jmap : jmap -dump:file=D:\mon\filepath\dump.bin javaProcessPid
Pour récupérer le pid d'un process java, le command line tool jps les liste, sous windows on peut également les retrouver via le task manager et sous linux "ps -eaf | grep java" permet généralement de s'en sortir.
Si l'on veut faire une génération en programmatique il est facile d'effectuer le code suivant :
//get my process pid
String name = ManagementFactory.getRuntimeMXBean().getName();
String pid = name.substring(0, name.indexOf("@"));
//prepare launch
String[] cmd = { "jmap", "-dump:file=D:\\dump.bin", pid };
try {
//exec jmap process
Process p = Runtime.getRuntime().exec(cmd);
} catch (IOException e) {
System.out.println("InterruptedException " + e);
}
Une fois le dump généré, il y a la deuxième partie, sa lecture. Pour ce faire (en dehors des outils du marché, on ne les a pas toujours à disposition) :
- MAT : Memory Analyzer d'Eclipse (http://www.eclipse.org/mat/)
- jhat en command line tool fourni avec le jdk. "jhat dump.bin", il ouvre un petit serveur http présentant les résultat, accessible via http://localhost:7000/
Ce dernier donne un résultat peu enrichie mais il facilement accessible étant dans le jdk. A noter aussi que jhat peut faire une comparaison basé sur un baseline dump et ainsi marquer les nouveaux objets (http://docs.oracle.com/javase/6/docs/technotes/tools/share/jhat.html).
Jmap (http://docs.oracle.com/javase/7/docs/technotes/tools/share/jmap.html) présente également quelques options intéressantes qui sans aller jusqu'au dump complet fournissent des informations utiles (toujours en command line tool donc facilement accessible) :
- "jmap -histo:live javaPid" : sort l'histogramme du heap (liste des classes et nombre d'instances)
- "jmap -permstat javaPid" : donne les indication concernant le permgen space
- "jmap -heap javaPid" : permet d'avoir la composition du heap
A savoir pour -histo et -dump, jmap dispose d'un mode forcé (-F) qui même lorsque la jvm ne répond permet d'avoir une sortie d'information. Il m'ai déjà arriver avant que ma jvm ne tombe de ne plus pouvoir accéder via JConsole, ... et de quand même pouvoir sortir un minimum d'information grâce à ce mode Force.
ThreadDump
La encore un thread dump peut être généré runtime de différentes manière :
- via MBean java.lang:type=Threading, l'opération dumpAllThreads qui prend en paramètre deux boolean (lockedMonitors et lockedSynchronizers, voir http://docs.oracle.com/javase/7/docs/api/)
- via jstack en ligne de commande (http://docs.oracle.com/javase/7/docs/technotes/tools/share/jstack.html), il dispose également d'un mode Force en cas de jvm qui ne répond plus (-F)
L'analyse des stacks, lock et monitor permet de comprendre ce que l'application était en train de faire au moment de la génération du dump. Pour comprendre la composition d'un threaddump voir l'article
Un outil intéressant pour faciliter l'analyse des threaddump mjprof. Il s'utilise conjointement avec jstack et permet de filtrer, trier, manipuler les stacks.
- Site du projet : https://github.com/lifey/mjprof
- Article : http://blog.performize-it.com/2014/05/mjstack-mjprof.html
- Article : http://blog.performize-it.com/2014/03/mjstack-monadic-jstack-analyzer.html
Observation Runtime
Tout les éléments précédemment abordés permettent de collecter des données figées (logs, dump, ....) mais il est aussi intéressant de suivre en temps réel l'évolution. Ce peut être fait en rapprochant les photos (dump) et comparant leurs valeurs. Mais il existe d'autres alternatives.
Entre deux modes, un outil jstat (http://docs.oracle.com/javase/1.5.0/docs/tooldocs/share/jstat.html) qui permet de produire quelques métriques avec un affichage continu rafraîchi sur une périodicité donnée.
Sinon pour suivre en temps réel ce qui se passe deux outils très bien, fourni de base avec le jdk :
- JConsole (jdk1.7.0_25\bin par exemple) http://docs.oracle.com/javase/7/docs/technotes/guides/management/jconsole.html
- VisualVM (jdk1.7.0_25\bin par exemple) qui est une version évoluée de la JConsole pouvant s'enrichir de quelques plugins. Avec VisualVM on peut commencer à faire du profiling visuel http://visualvm.java.net/
A noter également, qui se rapproche plus des Yourkit et JProfiler, Java Mission Control disponible à partir des jdk7u40. A tester et voir ce que cela va donner avec le temps (http://www.oracle.com/technetwork/java/javaseproducts/mission-control/java-mission-control-1998576.html)
En résumé
Sans outillage complexe, pour avoir de l'information sur une JVM qui tourne :
- Bilan des flags (jvm args) activés, positionnés, les settings de heap initiales, la GCPolicy en place
- Des logs à activer (GC, classloading, JIT)
- Dans le suivi runtime, deux aspects importants : la mémoire et les threads (consommation CPU)
- On peut les dumper ou interroger la jvm pour avoir des informations (command line tools sont nombreux et documentés) ou encore les suivre via des consoles (JConsole, VisualVM)
- Un mode force (-F) pour jstack et jmap, pratique quand une jvm ne répond plus
Quelques Références
Une présentation concernant les outils ligne de commande "Tout ce que vous avez toujours voulu savoir de la JVM sans jamais oser lui demander en ligne de commande" de Brice Leporini
- vidéo et slide de la présentation : http://www.parleys.com/play/53368d45e4b0dd67cb9eda8b/chapter0/about
- slides (la session ayant du coding, ce n'est pas le plus intéressant) : http://fr.slideshare.net/bleporini/devoxx-jvm-tools
- article sur la présentation : http://www.infoq.com/fr/articles/jvm-ligne-de-commande
Documentation OpenJDK
- http://openjdk.java.net/tools/
- http://openjdk.java.net/groups/serviceability/index.html#tools
- http://openjdk.java.net/tools/svc/jconsole/
Tuto Oracle sur les command line tools : http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/JavaJCMD/index.html
Pour compléter un point que je n'ai pas abordé, la JVM ouvre des points d'API permettant de l'interroger directement (souvent utiliser par les outils de monitoring)
- http://www.oracle.com/technetwork/articles/javase/jvmpitransition-138768.html
- http://jeremymanson.blogspot.fr/2007/05/profiling-with-jvmtijvmpi-sigprof-and.html
- http://www.jmdoudoux.fr/java/dej/chap-jvm.htm#jvm-7
Et après avoir investigué, observé ...
Fort de toutes ces métriques récoltées il est maintenant possible de passer à l'optimisation (et regarder leur impact) mais cela fera l'objet d'un autre billet.
La première "optimisation" si ce n'est pas fait est de bien sizer ses variables initiales :
- Taille du heap au démarrage et taille maximale : -Xms, -Xmx (il existe un débat concernant ce point, moi j'aime bien fixer à la même valeur pour éviter de resizer en cours d'utilisation)
- Taille max du permgen space : -XX:MaxPermSize qui vient en addition du Xmx et dont la valeur par défaut est 64 Mb
Un "jmap -heap" permettra de faire un bilan concernant les valeurs actuelles et la garbage policy utilisée.
Aller pour finir une dernière url concernant les optimisations : http://fr.slideshare.net/leonjchen/java-optimization-twjug
