Java JVM: monitorización de rendimiento desde CLI

Alex

hace 10 años

En esta entrada voy a dar un repaso a las herramientas que podemos utilizar desde línea de comandos (CLI) para monitorizar el rendimiento de una Java Virtual Machine (JVM). Como complemento a esta entrada podéis leer la que publiqué hace unos días sobre como generar un Java thread dump con OpenJDK y Tomcat ya que los comandos/herramientas jstack y jps es parte importante de este tipo de monitorización, lo tenéis explicado en ese artículo con mayor detalle. También podéis revisar como acceder a una monitorización de Java a través de JXM y jConsole en modo gráfico.

Los comandos básicos que podemos utilizar para monitorizar una JVM desde CLI son los siguientes:

jps
jstat
jstack
jcmd

jps

Como ya comenté en la entrada que he citado anteriormente sobre generar un Java Thread Dump, el comando jps simplemente muestra por salida estándar los PID (lvmid) de los procesos java que hay ejecutandose en el sistema junto con el nombre de la clase que se está utilizando y sus argumentos. Es como el comando ps de *nix pero adaptado a Java.

Modo de utilización:

jps [-q] [-mlvV] [<hostid>]

Ejemplo:

# jps -mlvV
1645 org.apache.catalina.startup.Bootstrap start 
-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory 
-Dcatalina.base=/usr/share/tomcat6 -Dcatalina.home=/usr/share/tomcat6 
-Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat6/temp 
-Djava.util.logging.config.file=/usr/share/tomcat6/conf/logging.properties 
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
1691 sun.tools.jps.Jps -mlvV -Dapplication.home=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71 -Xms8m

Este comando nos servirá para sacar el PID de la JVM, necesario para poder empezar la monitorización del proceso con el resto de comandos (jstat, jstack…).

jcmd

El comando jcmd (ojo, disponible a partir de JDK 7) permite consultar información sobre las JVM al igual que jps, es más, si lo ejecutamos sin parámetros la información es la misma:

# jcmd 
1645 org.apache.catalina.startup.Bootstrap start
1709 sun.tools.jcmd.JCmd

# jcmd -l
1718 sun.tools.jcmd.JCmd -l
1645 org.apache.catalina.startup.Bootstrap start

Para que nos muestre información más específica y no disponible con jps utilizamos los parámeteros que nos ofrece. Si atacamos al PID de una JVM concreta sí que podemos ver información de utilidad sobre ella que no nos ofrecía jps:

$ jcmd 1645 VM.system_properties
1645:
#Sat Nov 01 10:20:55 CET 2014
java.runtime.name=OpenJDK Runtime Environment
sun.boot.library.path=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/i386
java.vm.version=24.65-b04
shared.loader=
java.vm.vendor=Oracle Corporation
java.vendor.url=http\://java.oracle.com/
path.separator=\:
java.vm.name=OpenJDK Client VM
tomcat.util.buf.StringCache.byte.enabled=true
file.encoding.pkg=sun.io
java.util.logging.config.file=/usr/share/tomcat6/conf/logging.properties
user.country=US
sun.java.launcher=SUN_STANDARD
sun.os.patch.level=unknown
java.vm.specification.name=Java Virtual Machine Specification
user.dir=/usr/share/tomcat6
java.runtime.version=1.7.0_71-mockbuild_2014_10_17_21_54-b00
java.awt.graphicsenv=sun.awt.X11GraphicsEnvironment
java.endorsed.dirs=
os.arch=i386
javax.accessibility.assistive_technologies=org.GNOME.Accessibility.JavaBridge
java.io.tmpdir=/var/cache/tomcat6/temp
line.separator=\n
java.vm.specification.vendor=Oracle Corporation
java.util.logging.manager=org.apache.juli.ClassLoaderLogManager
java.naming.factory.url.pkgs=org.apache.naming
os.name=Linux
sun.jnu.encoding=UTF-8
java.library.path=/usr/java/packages/lib/i386\:/lib\:/usr/lib
java.specification.name=Java Platform API Specification
java.class.version=51.0
sun.management.compiler=HotSpot Client Compiler
os.version=2.6.32-279.el6.i686
user.home=/usr/share/tomcat6
catalina.useNaming=true
user.timezone=Europe/Madrid
java.awt.printerjob=sun.print.PSPrinterJob
file.encoding=UTF-8
java.specification.version=1.7
catalina.home=/usr/share/tomcat6
java.class.path=\:/usr/share/tomcat6/bin/bootstrap.jar\:/usr/share/tomcat6/bin/tomcat-juli.jar\:/usr/share/java/commons-daemon.jar
user.name=tomcat
java.naming.factory.initial=org.apache.naming.java.javaURLContextFactory
package.definition=sun.,java.,org.apache.catalina.,org.apache.coyote.,org.apache.tomcat.,org.apache.jasper.
javax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory
java.vm.specification.version=1.7
sun.java.command=org.apache.catalina.startup.Bootstrap start
java.home=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre
sun.arch.data.model=32
user.language=en
java.specification.vendor=Oracle Corporation
awt.toolkit=sun.awt.X11.XToolkit
java.vm.info=mixed mode, sharing
java.version=1.7.0_71
java.ext.dirs=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/ext\:/usr/java/packages/lib/ext
sun.boot.class.path=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/resources.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/rt.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/sunrsasign.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/jsse.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/jce.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/charsets.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/rhino.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/jfr.jar\:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/classes
server.loader=
java.vendor=Oracle Corporation
catalina.base=/usr/share/tomcat6
file.separator=/
java.vendor.url.bug=http\://bugreport.sun.com/bugreport/
common.loader=${catalina.base}/lib,${catalina.base}/lib/*.jar,${catalina.home}/lib,${catalina.home}/lib/*.jar
sun.font.fontmanager=sun.awt.X11FontManager
sun.io.unicode.encoding=UnicodeLittle
sun.cpu.endian=little
package.access=sun.,org.apache.catalina.,org.apache.coyote.,org.apache.tomcat.,org.apache.jasper.,sun.beans.
sun.cpu.isalist=

Ya tenemos un volcado con un montón de información de la JVM. Vemos información relacionada con:

VM.native_memory
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
Thread.print
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version

Podemos invocar por separado cada propiedad para evitar un volcado tan grande de información. Si queremos ver, por ejemplo, información de los Threads en ejecución ejecutaríamos lo siguiente. Si os fijáis, es lo mismo que la ejecución del jstack, que utilizabamos para generar un thread dump:

$ jcmd 1645 Thread.print
1645:
2014-11-01 10:25:00
Full thread dump OpenJDK Client VM (24.65-b04 mixed mode, sharing):

"Attach Listener" daemon prio=10 tid=0xb763b800 nid=0x6f6 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"TP-Monitor" daemon prio=10 tid=0xb763a000 nid=0x69a in Object.wait() [0xb47ba000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on  (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
	at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565)
	- locked  (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
	at java.lang.Thread.run(Thread.java:745)

"TP-Processor4" daemon prio=10 tid=0xb7638400 nid=0x699 runnable [0xb480b000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
	at java.net.ServerSocket.implAccept(ServerSocket.java:530)
	at java.net.ServerSocket.accept(ServerSocket.java:498)
	at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:307)
	at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:661)
	at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:872)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
	at java.lang.Thread.run(Thread.java:745)

"TP-Processor3" daemon prio=10 tid=0xb7636800 nid=0x698 in Object.wait() [0xb485c000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on  (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
	at java.lang.Object.wait(Object.java:503)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
	- locked  (a org.apache.tomcat.util.threads.ThreadPool$Co
[...]

Las posibilidades son muy amplias, también podemos, por ejemplo, visualizar un volcado de todos los contadores relacionados con el rendimiento de la JVM:

$ jcmd 1645 GC.heap_dump PerfCounter.print 
1645:
java.ci.totalTime=1455540
java.cls.loadedClasses=941
java.cls.sharedLoadedClasses=651
java.cls.sharedUnloadedClasses=0
java.cls.unloadedClasses=0
java.property.java.class.path=":/usr/share/tomcat6/bin/bootstrap.jar:/usr/share/tomcat6/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar"
java.property.java.endorsed.dirs=""
java.property.java.ext.dirs="/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre/lib/ext:/usr/java/packages/lib/ext"
java.property.java.home="/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.71/jre"
java.property.java.library.path="/usr/java/packages/lib/i386:/lib:/usr/lib"
java.property.java.version="1.7.0_71"
java.property.java.vm.info="mixed mode, sharing"
java.property.java.vm.name="OpenJDK Client VM"
java.property.java.vm.specification.name="Java Virtual Machine Specification"
java.property.java.vm.specification.vendor="Oracle Corporation"
java.property.java.vm.specification.version="1.7"
java.property.java.vm.vendor="Oracle Corporation"
java.property.java.vm.version="24.65-b04"
java.rt.vmArgs="-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcatalina.base=/usr/share/tomcat6 -Dcatalina.home=/usr/share/tomcat6 -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat6/temp -Djava.util.logging.config.file=/usr/share/tomcat6/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager"
java.rt.vmFlags=""
java.threads.daemon=12
java.threads.live=13
java.threads.livePeak=13
java.threads.started=13
sun.ci.compilerThread.0.compiles=309
sun.ci.compilerThread.0.method=""
sun.ci.compilerThread.0.time=6089
sun.ci.compilerThread.0.type=1
sun.ci.lastFailedMethod=""
sun.ci.lastFailedType=0
sun.ci.lastInvalidatedMethod=""
sun.ci.lastInvalidatedType=0
sun.ci.lastMethod="java/lang/String getBytes"
sun.ci.lastSize=27
sun.ci.lastType=1
sun.ci.nmethodCodeSize=228688
sun.ci.nmethodSize=575040
sun.ci.osrBytes=0
sun.ci.osrCompiles=0
sun.ci.osrTime=0
sun.ci.standardBytes=52071
sun.ci.standardCompiles=309
sun.ci.standardTime=1455540
sun.ci.threads=1
sun.ci.totalBailouts=0
sun.ci.totalCompiles=309
sun.ci.totalInvalidates=0
sun.classloader.findClassTime=1961005332
sun.classloader.findClasses=251
sun.classloader.parentDelegationTime=899720500
sun.cls.appClassBytes=1329461
sun.cls.appClassLoadCount=488
sun.cls.appClassLoadTime=2268616
sun.cls.appClassLoadTime.self=1166487
sun.cls.classInitTime=5150627
sun.cls.classInitTime.self=3333236
sun.cls.classLinkedTime=1528211
sun.cls.classLinkedTime.self=144025
sun.cls.classVerifyTime=1313279
sun.cls.classVerifyTime.self=483593
sun.cls.defineAppClassTime=655180
sun.cls.defineAppClassTime.self=69185
sun.cls.defineAppClasses=271
sun.cls.initializedClasses=1181
sun.cls.isUnsyncloadClassSet=0
sun.cls.jniDefineClassNoLockCalls=0
sun.cls.jvmDefineClassNoLockCalls=38
sun.cls.jvmFindLoadedClassNoLockCalls=1075
sun.cls.linkedClasses=1420
sun.cls.loadInstanceClassFailRate=0
sun.cls.loadedBytes=1131600
sun.cls.lookupSysClassTime=2295064
sun.cls.methodBytes=800392
sun.cls.nonSystemLoaderLockContentionRate=1
sun.cls.parseClassTime=1700604
sun.cls.parseClassTime.self=1159188
sun.cls.sharedClassLoadTime=1412946
sun.cls.sharedLoadedBytes=816344
sun.cls.sharedUnloadedBytes=0
sun.cls.sysClassBytes=2491030
sun.cls.sysClassLoadTime=3954269
sun.cls.systemLoaderLockContentionRate=0
sun.cls.time=8982118
sun.cls.unloadedBytes=0
sun.cls.unsafeDefineClassCalls=20
sun.cls.verifiedClasses=824
sun.gc.cause="No GC"
sun.gc.collector.0.invocations=5
sun.gc.collector.0.lastEntryTime=11849108
sun.gc.collector.0.lastExitTime=11871701
sun.gc.collector.0.name="Copy"
sun.gc.collector.0.time=192835
sun.gc.collector.1.invocations=0
sun.gc.collector.1.lastEntryTime=0
sun.gc.collector.1.lastExitTime=0
sun.gc.collector.1.name="MSC"
sun.gc.collector.1.time=0
sun.gc.generation.0.agetable.bytes.00=0
sun.gc.generation.0.agetable.bytes.01=393216
sun.gc.generation.0.agetable.bytes.02=0
sun.gc.generation.0.agetable.bytes.03=0
sun.gc.generation.0.agetable.bytes.04=0
sun.gc.generation.0.agetable.bytes.05=0
[...]

La información puede ser abrumadora, lo sé, así que lo recomendable es localizar los parámetros y valores que realmente necesitamos para nuestra monitorización del rendimiento de la JVM y procesarlos como estimemos oportuno (scripts, gráficas, etc).

jstat

El comando jstat muestra información detallada y estadísticas de la JVM.

Lo más básico a conocer es la forma de mostrar información sobre el Garbage Collector (GC). Para ello se utiliza el parámetro -gctuil junto con el PID de la JVM que obtenemos con jps o jcmd:

$ jstat -gcutil 1645
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  44.35  38.48  31.63      5    0.193     0    0.000    0.193

Para visualizar la información a tiempo real en un intervalo específico de tiempo añadimos como parámetro el tiempo en milisegundos. En el siguiente ejemplo se muestra la información cada 2 segundos para la JVM con el PID 1645:

$ jstat -gcutil 1645 2000
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  44.35  38.48  31.63      5    0.193     0    0.000    0.193
  0.00 100.00  44.35  38.48  31.63      5    0.193     0    0.000    0.193
  0.00 100.00  44.35  38.48  31.63      5    0.193     0    0.000    0.193
[...]

La explicación de los valores de cada columna son los siguientes:

S0: Survivor space 0. Porcentaje de utilización sobre la capacidad total del espacio de memoria.
S1: Survivor space 1. Porcentaje de utilización sobre la capacidad total del espacio de memoria.
E: Eden space. Porcentaje de utilización sobre la capacidad total del espacio de memoria.
O: Old space. Porcentaje de utilización sobre la capacidad total del espacio de memoria.
P: Permanent space. Porcentaje de utilización sobre la capacidad total del espacio de memoria.
YGC: número de eventos de «young generation GC» generados.
YGCT: Tiempo de garbage collection utilizada por los eventos «Young generation».
FGC: número total de eventos en el GC.
FGCT: tiempo utilizado para un GC completo.
GCT: tiempo total utilizado para eventos de GC.

jstack

Al comienzo del artículo tenéis el link a la entrada en la que hablo sobre jstack. Básicamente jstack permite generar un «thread dump» de Java, es decir, un volcado de todos los hilos que hay en ejecución en una JVM (Java Virtual Machine).

$ jstack 1645 | more
2014-11-01 10:44:01
Full thread dump OpenJDK Client VM (24.65-b04 mixed mode, sharing):

"Attach Listener" daemon prio=10 tid=0xb763b800 nid=0x6f6 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"TP-Monitor" daemon prio=10 tid=0xb763a000 nid=0x69a in Object.wait() [0xb47ba000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on  (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
	at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565)
	- locked  (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
	at java.lang.Thread.run(Thread.java:745)

"TP-Processor4" daemon prio=10 tid=0xb7638400 nid=0x699 runnable [0xb480b000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
	at java.net.ServerSocket.implAccept(ServerSocket.java:530)
	at java.net.ServerSocket.accept(ServerSocket.java:498)
	at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:307)
	at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:661)
	at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:872)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
	at java.lang.Thread.run(Thread.java:745)
[...]

El dump se genera en STDOUT así que es conveniente redirigirlo a un archivo:

$ jstack 1645 > dump.out

Este comando es muy importante para visualizar si hay threads bloqueados o esperando ya que nos muestra el estado del thread: NEW, RUNNABLE, BLOCKED, WAITING, TIMED_WAITING junto con la excepción e información del hilo.

En resumen, conociendo estos comandos, su utilización básica y combinandolos con herramientas gráficas como jConsole y JMX podemos tener una buena visión del estado, rendimiento y propiedades de la JVM y el funcionamiento del servidor de aplicaciones.