Activación de logs de recolección de basura en la JVM

Monitorear y entender el proceso de recolección de basura es una de las claves para optimizar el rendimiento de una máquina virtual, pues es precisamente este proceso el que genera un mayor impacto en los tiempos de respuesta de una aplicación en ejecución cuando los otros elementos asociados (hardware, redes, sistema operativo, entre otros) están funcionando de manera adecuada.

La activación de este log se hace a través de parámetros de arranque de la JVM ya sea escribiéndolos directamente en los parámetros de inicio de una aplicación, con una variable de entorno para un servidor de aplicaciones o usando la consola de administración de una instancia, cluster, etc.

Tenga en cuenta que las opciones de arranque y estructura de logs varían entre diferentes máquinas virtuales.


Java HotSpot

Las opciones disponibles para la geeración de logs son las siguientes:

  • -verbose:gc: activa la generación de logs con el formato por defecto que tiene la siguiente apariencia para recolecciones menores y mayores:

[Full GC 16696K->11801K(83008K), 0.1271927 secs]

[GC 28825K->12105K(83008K), 0.0033376 secs]

  • -XX:+PrintGCDateStamps: incluye información sobre la fecha y hora de la recolección de basura, la estructura del log es la siguiente:

2012-05-03T23:04:26.955-0500: [Full GC 29883K->12887K(83008K), 0.1381200 secs]

2012-05-03T23:05:44.118-0500: [GC 29911K->13488K(83008K), 0.0022940 secs]

Note que la primera parte corresponde a la fecha y hora de recolección.

  • -XX:+PrintGCDetails: imprime datos adicionales sobre las secciones en que se divide la memoria heap con la siguiente estructura:

2012-05-03T23:20:14.819-0500: [Full GC (System) [CMS: 12594K->11578K(63872K), 0.1319746 secs] 17095K->11578K(83008K), [CMS Perm : 41162K->40914K(41216K)], 0.1321077 secs] [Times: user=0.14 sys=0.00, real=0.14 secs] 

2012-05-03T23:21:36.540-0500: [GC [ParNew: 17024K->821K(19136K), 0.0019971 secs] 28602K->12400K(83008K), 0.0020616 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

  • -XX:+PrintHeapAtGC: muestra la distribución de memoria heap antes y después de una recolección de basura.

{Heap before GC invocations=18 (full 3):
par new generation total 19136K, used 9927K [7f3000000, 7f44c0000, 7f44c0000)
eden space 17024K, 54% used [7f3000000, 7f391faf0, 7f40a0000)
from space 2112K, 27% used [7f42b0000, 7f43421b0, 7f44c0000)
to space 2112K, 0% used [7f40a0000, 7f40a0000, 7f42b0000)
concurrent mark-sweep generation total 63872K, used 11795K [7f44c0000, 7f8320000, 7fae00000)
concurrent-mark-sweep perm gen total 68824K, used 41233K [7fae00000, 7ff136000, 800000000)

2012-05-04T00:16:42.677-0500: [Full GC (System) [CMS: 11795K->11789K(63872K), 0.1186983 secs] 21723K->11789K(83008K), [CMS Perm : 41233K->41231K(68824K)], 0.1187874 secs] [Times: user=0.12 sys=0.00, real=0.12 secs]

Heap after GC invocations=19 (full 4):
par new generation total 19136K, used 0K [7f3000000, 7f44c0000, 7f44c0000)
eden space 17024K, 0% used [7f3000000, 7f3000000, 7f40a0000)
from space 2112K, 0% used [7f42b0000, 7f42b0000, 7f44c0000)
to space 2112K, 0% used [7f40a0000, 7f40a0000, 7f42b0000)
concurrent mark-sweep generation total 63872K, used 11789K [7f44c0000, 7f8320000, 7fae00000)
concurrent-mark-sweep perm gen total 68824K, used 41231K [7fae00000, 7ff136000, 800000000)

}

  • -XX:+PrintTenuringDistribution:

{Heap before GC invocations=22 (full 3):
par new generation total 19136K, used 17350K [7f3000000, 7f44c0000, 7f44c0000)
eden space 17024K, 100% used [7f3000000, 7f40a0000, 7f40a0000)
from space 2112K, 15% used [7f42b0000, 7f43019d8, 7f44c0000)
to space 2112K, 0% used [7f40a0000, 7f40a0000, 7f42b0000)
concurrent mark-sweep generation total 63872K, used 10398K [7f44c0000, 7f8320000, 7fae00000)
concurrent-mark-sweep perm gen total 68628K, used 41032K [7fae00000, 7ff105000, 800000000)

2012-05-04T00:45:26.595-0500: [GC [ParNew
Desired survivor size 1081344 bytes, new threshold 4 (max 4)
- age 1: 70424 bytes, 70424 total
- age 2: 93288 bytes, 163712 total

Heap after GC invocations=23 (full 3):
par new generation total 19136K, used 241K [7f3000000, 7f44c0000, 7f44c0000)
eden space 17024K, 0% used [7f3000000, 7f3000000, 7f40a0000)
from space 2112K, 11% used [7f40a0000, 7f40dc758, 7f42b0000)
to space 2112K, 0% used [7f42b0000, 7f42b0000, 7f44c0000)
concurrent mark-sweep generation total 63872K, used 10398K [7f44c0000, 7f8320000, 7fae00000)
concurrent-mark-sweep perm gen total 68628K, used 41032K [7fae00000, 7ff105000, 800000000)
}

  • -Xloggc:nombre_archivo: envía la salida del log a un archivo con el nombre especificado.


JRockit

  • -XgcReport: no funciona en la última versión.
  • -Xverbose:gcreport: al finalizar la ejecución de la máquina virtual imprime un resumen de las recolecciones de basura ejecutadas:

[INFO ][gcrepor]
[INFO ][gcrepor] Memory usage report:
[INFO ][gcrepor]
[INFO ][gcrepor] Young Collections:
[INFO ][gcrepor] number of collections = 69.
[INFO ][gcrepor] total promoted = 1049086 (size 148542416).
[INFO ][gcrepor] max promoted = 78127 (size 24478608).
[INFO ][gcrepor] total YC time = 4.151 s (total paused 3.528 s).
[INFO ][gcrepor] mean YC time = 60.156 ms (mean total paused 51.128 ms).
[INFO ][gcrepor] maximum YC Pauses = 127.220 , 163.864, 164.446 ms.
[INFO ][gcrepor]
[INFO ][gcrepor] Old Collections:
[INFO ][gcrepor] number of collections = 15.
[INFO ][gcrepor] total promoted = 0 (size 0).
[INFO ][gcrepor] max promoted = 0 (size 0).
[INFO ][gcrepor] total OC time = 2.403 s (total paused 2.159 s).
[INFO ][gcrepor] mean OC time = 160.183 ms (mean total paused 143.937 ms).
[INFO ][gcrepor] maximum OC Pauses = 240.275 , 295.795, 308.585 ms.
[INFO ][gcrepor]
[INFO ][gcrepor]
[INFO ][gcrepor] number of internal compactions = 7.
[INFO ][gcrepor] number of external compactions = 8.
[INFO ][gcrepor]

  • -XgcPause: no funciona en la última versión.
  • -Xverbose:gcpause: muestra en tiempo de ejecución los tiempos de pausa generados por la recolección de basura.

[INFO ][gcpause] [YC#33] [—-] 34.873 ms (97.122000-97.157000) YC
[INFO ][gcpause] [YC#33] [con] 0.029 ms (97.122000-97.122000) YC:PreGC
[INFO ][gcpause] [YC#33] [pau] 27.435 ms (97.122000-97.150000) YC:Main
[INFO ][gcpause] [YC#33] [con] 7.284 ms (97.150000-97.157000) YC:PostGC

[INFO ][gcpause] [OC#8] [—-] 123.507 ms (97.602000-97.726000) OC
[INFO ][gcpause] [OC#8] [con] 0.008 ms (97.602000-97.602000) OC:PreGC
[INFO ][gcpause] [OC#8] [pau] 115.642 ms (97.602000-97.718000) OC:Main
[INFO ][gcpause] [OC#8] [con] 7.705 ms (97.718000-97.726000) OC:PostGC

  • -Xverbose:memory: imprime información acerca de la gestión de memoria. La salida cambia de acuerdo al recolector de basura seleccionado.

[INFO ][memory ] Running with 32 bit heap and compressed references.
[INFO ][memory ] GC mode: Garbage collection optimized for throughput, strategy: Generational Parallel Mark & Sweep.
[INFO ][memory ] Heap size: 65536KB, maximal heap size: 764616KB, nursery size: 32768KB.
[INFO ][memory ] <start>-<end>: <type> <before>KB-><after>KB (<heap>KB), <time> ms, sum of pauses <pause> ms.
[INFO ][memory ] <start> - start time of collection (seconds since jvm start).
[INFO ][memory ] <type> - OC (old collection) or YC (young collection).
[INFO ][memory ] <end> - end time of collection (seconds since jvm start).
[INFO ][memory ] <before> - memory used by objects before collection (KB).
[INFO ][memory ] <after> - memory used by objects after collection (KB).
[INFO ][memory ] <heap> - size of heap after collection (KB).
[INFO ][memory ] <time> - total time of collection (milliseconds).
[INFO ][memory ] <pause> - total sum of pauses during collection (milliseconds).
[INFO ][memory ] Run with -Xverbose:gcpause to see individual phases.

[INFO ][memory ] [YC#39] 240.480-240.592: YC 80266KB->67677KB (94376KB), 0.111 s, sum of pauses 99.689 ms, longest pause 99.689 ms.

[INFO ][memory ] [OC#10] 150.948-151.112: OC 84426KB->37348KB (94376KB), 0.164 s, sum of pauses 135.670 ms, longest pause 135.670 ms.

  • -Xverbose:memdbg: imprime opciones de memoria adicionales.

[DEBUG][memory ] [YC#25] GC reason: Allocation request failed.
[DEBUG][memory ] [YC#25] 30.893: YC started.
[INFO ][alloc ] [YC#25] Pending requests at 'Before YC' - Total: 1, TLAs: 1 (approx 65536 bytes), objects: 0 (0 bytes). Max age: 0.
[INFO ][nursery] [YC#25] Young collection 25 started. This YC is running while the OC is in phase: not running.

[INFO ][nursery] [YC#25] Next keeparea will start at 0xd210cf08 and end at 0xd230b2b0.
[INFO ][alloc ] [YC#25] Satisfied 0 object and 1 tla allocations. Pending requests went from 1 to 0.
[INFO ][alloc ] [YC#25] Pending requests at 'After YC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.

[DEBUG][memory ] Adding 18 final handles from dying thread 'hudson initialization thread'.
[DEBUG][memory ] [YC#26] GC reason: Allocation request failed.
[DEBUG][memory ] [YC#26] 85.532: YC started.
[INFO ][alloc ] [YC#26] Pending requests at 'Before YC' - Total: 1, TLAs: 1 (approx 65536 bytes), objects: 0 (0 bytes). Max age: 0.

[INFO ][nursery] [YC#26] Young collection 26 started. This YC is running while the OC is in phase: not running.

[INFO ][nursery] [YC#26] Next keeparea will start at 0xd1f19730 and end at 0xd210cf08.
[INFO ][alloc ] [YC#26] Satisfied 0 object and 1 tla allocations. Pending requests went from 1 to 0.
[INFO ][alloc ] [YC#26] Pending requests at 'After YC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.

[DEBUG][memory ] [YC#26] YC promoted 10008 objects (436KB).
[DEBUG][memory ] [YC#26] Page faults before YC: 1, page faults after YC: 1, pages in heap: 28313.
[DEBUG][memory ] [YC#26] Nursery size after YC: 7538KB. (Free: 5635KB Parts: 329)

  • -XXprintSystemGC: no funciona en la última versión.


Configuración en Apache Tomcat

Existen varias opciones para configurar estos valores de arranque, para Apache Tomcat la más adecuada es ajustar la variable CATALINA_OPTS ya sea en los archivos de arranque del servidor o configurándola como variable de entorno. Por ejemplo puede combinar varias opcines de -Xverbose en Linux mediante el comando export:

export CATALINA_OPTS="-Xverbose:gcreport,gcpause,memory,memdbg"


Recursos adicionales:

Si no se indica lo contrario, el contenido de esta página se ofrece bajo Creative Commons Attribution-ShareAlike 3.0 License