Estado de la JVM: hilos, objetos en memoria y GC

por | mayo 2, 2019
0 comentarios

Existen multitud de herramientas para poder revisar el estado de los objetos en memoria, threads y GC de una JVM. Algunas son simples funcionalidades que añadimos como opciones Java al iniciar una JVM mientras que otras son herramientas externas que nos permiten acceder a su estado interno para revisar distintos parámetros.

Volcados de memoria

Útiles para analizar la causa de un OutOfMemory debido a un problema de aplicación o simplemente para determinar qué objetos hay cargados en memoria en un momento dado.

  • En primer lugar podemos echar mano de la utilidad jmap: 
    jmap -dump:format=b,file=<file_name> <pid>

    Ejemplo:

    jmap -dump:format=b,file=jboss-app1.hprof 9257

    Podemos utilizar jmap en cualquier momento, pero si lo haces en producción ten en cuenta que al lanzarla la JVM detiene toda su actividad (se «congela») hasta que se complete el volcado, algo que por otra parte es lógico ya que queremos analizar justamente en qué estado se encuentra la JVM en un momento específico.

  • La segunda opción es generar automáticamente un volcado de memoria en caso de OutOfMemory. Tendremos que pasarle los siguientes argumentos a la JVM al arrancarla: 
    -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath="/path/to/dir/dump.hprof"

    • Una vez obtenido el volcado por un método u otro podemos analizarlo con Eclipse Memory Analyser Tooling (MAT)

Volcados de hilos con jstack

Como los volcados de memoria, podemos querer sacar un volcado de hilos tanto por un problema (ej.:deadlock) como para conocer el estado de una JVM en un momento específico.

jstack [opciones] [PID]

Por ejemplo, utilizando la opción -l (long) para tener información adicional de los hilos en ejecución:

[jota@london-jota-node1 bin]$ jstack -l 3309
2019-04-16 21:25:09
Full thread dump OpenJDK 64-Bit Server VM (25.212-b01 mixed mode):

"ServerService Thread Pool -- 67" #128 prio=5 os_prio=0 tid=0x0000561db8e1c800 nid=0xdad waiting on condition [0x00007fd28af01000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000fca00760> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at org.jboss.threads.JBossThread.run(JBossThread.java:320)

   Locked ownable synchronizers:
	- None

"ServerService Thread Pool -- 66" #127 prio=5 os_prio=0 tid=0x0000561db6216000 nid=0xda3 waiting on condition [0x00007fd289c01000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000fca00760> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
	at org.jboss.threads.JBossThread.run(JBossThread.java:320)
...

Podemos volcarlos a un fichero para analizarlos posteriormente: 

jstack -l PID > threads.txt

Después se puede abrir con un editor cualquiera ya que es de texto plano. No obstante tenemos herramientas que facilitan el análisis como ThreadLogic o Thread Dump Analyzer (TDA)

Incluso hay herramientas online para ello.

Memoria de la JVM: Garbage Collection

    El estado de memoria de la propia JVM podemos verlo de diversas formas:

  • Pasarle a la JVM al arrancar una serie de argumentos que especifican dónde se deja el log, tamaño, número de ficheros de rotado, etc…: 
    -XX:+PrintGCDetails
-Xloggc:/path/to/dir/gclog.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=2000k

    Obtendremos un fichero gclog.log donde está todo el histórico de memoria de la JVM. Más tarde podemos analizar este log con herramientas como HP Jmeter o incluso herramientas online como GCEasy

  • Otra opción que no depende de opciones Java pasadas a la JVM es utilizar una herramienta como VisualGC de la que ya hablamos hace tiempo, que hace un attach a un proceso Java y permite visualizar el estado de la memoria. El único inconveniente es que no permite visualizar un histórico de uso de memoria de la JVM.

  • Tenemos también Grafana como herramienta de visualización de métricas de la JVM además de muchas otras. La implementación dependerá de diversos factores: qué recolector utilicemos (Collectd, Telegraf, etc…) y Base de Datos en la que almacenar dichas métricas (InfluxDB, Prometheus…) Normalmente necesitaremos desplegar alguna librería adicional como interfaz para poder acceder a las métricas de la JVM.

  • Otra herramienta de la que ya hablamos y que nos permite echar un vistazo al estado de la memoria de una JVM es jvm-mon. No se encuentra en la distribución de binarios de JRE o JDK, sino que se trata de un proyecto independiente de Andrejs Jermakovics.
  • Finalmente tenemos una utilidad alternativa de la propia JDK llamada jstat que nos permite ver el estado de la memoria de una JVM, con todas sus generaciones (old, eden, survivor,etc…) además del tiempo empleado en Parcial y Full GCs. Por ejemplo para ver el estado de recolección de memoria (puedes revisar todas las funcionalidades en la página man de la herramienta): 
    [root@london-jota-node1]# jstat -gcutil 749
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   8.81  26.62  31.37  82.12  76.30    237    2.374     4    0.194    2.568

    Donde cada columna es:

    • S0 -> Survivor 0
    • S1 -> Survivor 1
    • E -> Generación Eden
    • O -> Generación Old
    • M -> Metaespacios
    • YGC -> Número de Parcial GCs
    • YGCT -> Tiempo en hacer un Parcial GC.
    • FGC -> Número de Full GCs
    • FGCT -> Tiempo en hacer un GC Full.
    • GCT -> Tiempo total que se tarda en hacer un GC (Parcial + Full)

Como vemos existen multitud de herramientas que nos permiten de una forma u otra revisar el estado de nuestras JVM. En el artículo he incluído las que conozco y me han sido útiles en algún momento.