Monitorización y profiling con Java Mission Control y Java Flight Recorder

En este tutorial presentaremos un pequeño viaje por las funcionalidades más básicas de Java Mission Control y Java Flight Recorder como herramientas de monitorización y profiling de aplicaciones en Java

0. Índice de contenidos

1. Introducción

Java Mission Control (JCM a partir de ahora) es una herramienta de monitorización y gestión de aplicaciones Java propia de Oracle que minimiza el overhead habitual entre las herramientas de este tipo (menos del 1% del total de procesamiento).

Este bajo impacto en el rendimiento de las aplicaciones bajo monitorización se consigue gracias a que se alimenta de los datos que se generan de forma natural durante las optimizaciones dinámicas de la JVM. Aparte de minimizar este overhead de monitorización, este sistema de recolección de datos elimina el sesgo del observador, que se produce cuando las herramientas de este tipo alteran las características de ejecución de un sistema.

JMC está compuesto por la propia aplicación gráfica (JMC client) y una serie de plugins que se montan encima de la misma:

  • JVM Browser: Muestra las aplicaciones Java que se están ejecutando con sus respectivas JVMs. Cada una de las instancias de JVM se les denomina JVM Connection. Estas conexiones pueden ser locales por PID, o bien remotas por dirección de host.
  • JMX Console: Se conecta a una JVM en funcionamiento y recopila y presenta sus características en tiempo real, además de permitir la modificación de algunas de ellas en caliente gracias al uso de las Managed Beans. Desde esta consola es posible incluso definir reglas que se ejecuten cuando se cumpla cierta condición (por ejemplo, mandar un correo electrónico cuando el uso de CPU exceda el 80% durante más de 3 segundos.
  • Java Flight Recorder (JFR): Recopila y guarda información detallada del rendimiento de aplicaciones para un análisis futuro. Puede ser utilizado como una herramienta de monitorización de rendimiento independiente de JMC, pero cuando se usa en conjunción con esta presenta la información capturada de forma fácil en tablas, gráficas, etc.

Aunque pueda parecer “una herramienta más” de monitorización de JVM sumada a la ya extensa colección de dichas herramientas (jstat, jmx, VisualVM, HPJmeter, etc…), lo cierto es que resulta en la agrupación de las cosas buenas de cada una de ellas de forma clara y sencilla, con una interfaz gráfica muy amigable y con una capacidad de personalización tremenda.

Para simular carga de la máquina y obtener resultados más o menos “reales” se ha utilizado la suite de benchmarking del proyecto Opensource DaCapo Benchmark Suite.

2. Entorno

El tutorial está escrito usando el siguiente entorno:

  • Hardware: MacBook Pro Intel Core 2 Duo 8GB RAM.
  • Sistema Operativo: Mac OS Yosemite 10.10.3
  • Entorno de desarrollo: Eclipse Mars 4.5.0
  • Java JDK 1.7
  • DaCapo Benchmark Suite 9.12

3. Ejecución de JCM y JFR

Ya que JMC viene dentro del JDK de Oracle desde la versión 7u40, podemos ejecutarlo directamente desde la terminal (si tenemos añadido al $PATH el directorio del JDK):

Si queremos hacer uso de JFR para el profiling de aplicaciones, es necesario activar las siguientes dos opciones de la JVM:

Hay que tener que la JVM, por defecto, solo permite obtener trazas de ejecución en puntos seguros, por lo que podría darse el caso de que dichas trazas no sean correctas en ciertos casos. Es por ello que la documentación de JFR recomienda el uso de dos parámetros adicionales de la JVM, que no pueden ser modificados en caliente:

Es también posible arrancar directamente JFR al ejecutar la aplicación que queremos monitorizar desde la línea de comandos, lo que permite ahorrarnos técnicas para parar la ejecución hasta que tengamos toda la suite de monitorización lista (dormir el hilo principal de ejecución durante X segundos o realizar varias pasadas de calentamiento):

Si lo que queremos es monitorizar procesos en máquinas remotas, será necesario añadir los siguientes flags (que son específicos de JMX):

4. Consola JMX

Si hacemos click derecho sobre una de las conexiones en el JVM Browser podremos iniciar una nueva sesión de JMX Console:

Veamos cada una de las pestañas disponibles más interesantes án esta vista.

4.1. Overview

En esta pestaña se nos muestra un pequeño resumen de las métricas más comunes (uso de memoria y porcentaje de CPU). Nada especial aquí, sin embargo podremos añadir las métricas que JMX tenga disponible haciendo click en los signos de cada uno de los paneles.

4.2. MBean Browser

Desde aquí podremos acceder y visualizar todos los MBeans disponibles que nos proporciona JMX, con sus valores actuales y con la capacidad de poder añadirlos a las gr´ficas presentadas en la pantalla Overview.

Una funcionalidad que destaca de este panel es la capacidad de modificar ciertos parámetros de los MBeans en caliente haciendo doble click sobre los atributos con fondo amarillo (de esta manera JMC marca los que son modificables).

Al seleccionar un MBean, tendremos acceso a una serie de pestañas que nos permite ver información sobre sus atributos, operaciones (como llamar al garbage collector en el MBean “Memory”), notificaciones declaradas dado un comportamiento (lo veremos en el apartado de “Triggers”) y los metadatos del MBean.

4.3. Triggers

Una de las funcionalidades que, desde mi punto de vista, son más interesantes de la JMX Console de JMC es la capacidad de definir notificaciones de tal manera que cuando se cumpla una determinada condición sobre un MBean (o varios), se ejecute una determinada acción, entre las cuales se encuentran:

  • Popup de alerta.
  • Loggearlo en un archivo.
  • Enviar un correo electrónico con la información del evento.
  • Lanzar una sesión de Flight Recorder, tanto continua como limitada.
Además, en cada Trigger podremos definir entre qué intervalo de tiempos estará activa dicha condición, de tal manera que, por ejemplo, solo salte en días entre semana.

4.4. Threads

Desde aquí podremos ver todos los hilos de ejecución de nuestra aplicación, con información sobre su estado actual (ejecutándose, esperando, etc…), además de si se encuentran en una situación de deadlock (para lo cual hay que activar la detección de deadlocks en el checkbox superior), así como el total de memoria reservada para su contexto (que también deberemos de activar en la casilla “Allocation”).

Al seleccionar cualquiera de los hilos, podemos acceder a sus trazas de ejecución en el panel inferior, funcionalidad típica en herramientas de monitorización. Esta selección puede ser múltiple.

5. Java Flight Recorder

Como hemos visto en el apartado sobre ejecución de JMC y JFR es necesario añadir una serie de flags a la JVM de la aplicación que estemos monitorizando para que JFR pueda extraer estadísticas (si no lo hacemos, JMC nos avisará y podremos copiar estas opciones directamente del cuerpo de la ventana de error), recordémoslas:

Una vez ejecutada la aplicación, nos vamos a JMC y hacemos click derecho sobre la conexión correspondiente y seleccionamos “Start Flight Recording…”, lo que nos abrirá un wizard de configuración del JRF:

En este primer paso podremos dar un nombre al registro, así como elegir entre la recopilación en un determinado tiempo, que pueden ser segundos (unidad “s”), minutos (unidad “m”), horas (unidad “h”), días (unidad “d”) o semanas (unidad “w”). Una vez terminado este lapso de tiempo, el cliente de JMC se encargará automáticamente de guardar y abrir dicho registro.

La otra opción es hacer una recopilación continua (de la cual podremos definir un tamaño o tiempos máximos) y que no será guardado hasta que paremos la grabación. Este tipo de registro es necesario abrirlo explícitamente.

En el siguiente paso podremos personalizar una serie de preferencias sobre el muestreo de estadísticas, entre las que nos encontramos el comportamiento del garbage collector, el nivel de detalle del muestreo de los métodos, la frecuencia de los dumps de hilos o los umbrales de detección de actividad en operaciones de E/S (ficheros y sockets).

Además, podremos elegir si durante la recopilación queremos recoger estadísticas detalladas sobre el Heap, la carga de clases o la reserva de memoria dinámica.

Cuando abramos la grabación (que será un archivo con extensión *.jfr), nos encontraremos con la pantalla principal de JFR:

Desde aquí podremos acceder a las distintas partes principales del informe (a la izquierda, en forma de pestañas principales), además de las subsecciones en la parte inferior. En la parte superior se nos muestra la línea temporal de toda la grabación, en la cual, si arrastramos los bordes de la ventana, podremos definir un rango de tiempos que nos interese.

Es conveniente tener activada la opción “Synchronize Selection”, en la parte superior de la línea temporal, para que todas las pestañas del informe compartan el mismo instante de tiempo.

En esta primera sección podemos visualizar estadísiticas básicas sobre carga de CPU y uso de memoria en forma de gráfica la primera y en medidores de agujas. La subsección “JVM Information” nos hace un pequeño resumen sobre la configuración de la JVM y los flags con los que ha sido ejecutado.

Veamos lo que nos ofrece el resto de secciones:

5.1. Memory

Esta sección nos da información sobre todo lo que tenga que ver con la gestión de memoria que haya realizado la aplicación durante su ejecución con alto nivel de detalle.

En la primera subsección “Overview”, podemos visualizar la evolución del Heap con respecto al tiempo en forma de gráfica. En la parte superior podemos elegir qué métricas de tamaño queremos ver. Normalmente, como las aplicaciones no usan toda la memoria física de la máquina sobre la que está corriendo la JVM, será conveniente ocultar estas dos series de la gráfica para no aumentar en demasía el eje de ordenadas (en mi ejecución, el heap no crecía más de 600 MB).

Garbage Collections / GC Times

En estas subsecciones tenemos una información mucho más detallada sobre el comportamiento del GC, incluidas las duraciones de las pausas Stop-the-world (representadas como barras verticales rojas).

No sólo eso, si no que si seleccionamos uno de los ítems de la tabla “Garbage Collections”, se nos presentará una serie de métricas tomadas durante dicha pasada del GC:

  • Duración total de la pausa del GC.
  • Razón de la llamada al GC.
  • Tiempo empleado en cada una de las fases de la recolección.
  • Tipo de referencias de los objetos liberados.
  • Estado del Heap antes y después de la recolección.

Allocations

Esta pestaña es especialemnte útil (sobre todo “Allocation in New TLAB”) para comprobar qué clases son instanciadas más frecuentemente, cuánta memoria consumen y en qué partes del código son reservadas. Tenemos dos tipos distintos de análisis:

  • Reservas por clase.
  • Reservas por hilo.

En mi caso, casi el 90% de las reservas de memoria son del tipo char[] (cadenas de caracteres). Si hago click sobre este tipo de objetos, puedo ver que el 87% de dichas reservas se realizan en la clase StandardTokenizerImpl y que se concentran en los hilos “Query0” y “Query1”, si cambio a la vista “Allocation by Thread”.

5.2. Code

Esta sección es útil para realizar optimizaciones sobre el uso y tiempo de ejecución de CPU. En la subsección “Overview” tenemos dos vistas diferenciadas:

  • Hot Packages: Lista ordenada de los paquetes que están consumiendo más tiempo de CPU. Útil cuando estemos utilizando librerías de terceros y quieres tener resumenes separados de dichas librerías, de tu propio código y del propio JDK.
  • Hot Classes: Misma clasificación que la vista anterior, pero a nivel de clases.

Hot Methods / Call Tree

En estas vistas podemos ver una lista con los métodos que más utilizan más CPU, incluido el árbol de llamadas realizado hasta dichos métodos. Este ánalisis es el típico que podremos encontrar en cualquier herramienta de monitorización. Cuando queramos mejorar el rendimiento de nuestra aplicación, éste debería ser el primer sitio que visitemos en busca de cuellos de botella.

En ambas subsecciones tendremos la capacidad de filtrar los resultados por nombre de la traza, número total de llamadas o porcentaje de uso de CPU.

Exceptions

Aunque no sea clave en posibles mejoras de optimización de rendimiento debido a que, en principio, las excepciones deberían ser siempre usadas con sumo cuidado y solo en el caso de que sea estrictamente necesario. Sin embargo, ya que la gestión de excepciones suele ser una operación bastante costosa, si sospechamos que estamos manejando muchas excepciones, en esta vista podremos comprobar cuales son las más comunes e intentar llevarlas a un mínimo.

Compilations / Class Loading

Las últimas dos pestañas son bastante autoexplicativas y nos permiten comprobar los tiempos de compilación (tanto estándar cómo OSR) la primera y la carga y descarga de memoria de clases.

5.3. Threads

Esta sección detalla el comportamiento y rendimiento de los hilos de ejecución de la JVM. La principal ventaja de fijarse en estos resultados será la capacidad de detectar hilos bloqueantes en deadlock, latencias de espera y acceso a los dumps de trazas de ejecución de dichos hilos.

5.4. I/O

Esta sección nos permite inspeccionar la entrada/salida de nuestra aplicación tanto en fichero como por socket: número de lecturas y escrituras, tamaños y tiempos. Usualmente las métricas que nos interesará aquí son posibles operaciones sobre ficheros no esperados, múltiples aperturas/cierres del mismo fichero o que los tamaños sean muy pequeños.

Si se está haciendo uso de un disco SSD se recomienda poner el umbral de detección de eventos de lectura (“File Read Threshold”, en el wizard inicial de JFR) a 1ms, ya que, de lo contrario, podríamos perdernos muchos datos.

Las cuatro subsecciones son prácticamente idénticas en cuanto a visualizaciones, cada una encargándose de lectura/escritura de ficheros y sockets, por lo que solo nos detendremos en la primera de ellas.

Tenemos a nuestra disposición tres listas diferentes según el elemento: por fichero/socket (By File/Host), por hilo (By Thread) y por evento (By Event, que es una caombinación de las dos anteriores).

Si seleccionamos uno de los ítems, podremos inspeccionar una gráfica con las cantidades de bytes leídos/escritos por unidad de tiempo, lo que nos dará una idea de si es posible bajar, por ejemplo, los tiempos de lectura implementando una caché de datos.

5.5. Events

Esta sección nos permite visualizar todos, y repito TODOS, los eventos que se han producido durante la ejecución del programa y nos los muestre en porcentajes con respecto al tiempo total, ni por carga de CPU ni por uso de memoria.

Tenemos dos vistas separadas: por productores de carga arriba y por tipos de evento abajo. Si queremos añadir a las gráficas nuevos tipos de eventos, podremos hacerlo seleccionando uno de los disponibles en la lista de la izquierda.

Graph

La subsección más interesante desde mi punto de vista es esta, que nos permite ver en forma de línea temporal como se han comportado cada uno de los hilos del sistema; en qué momentos se encuentran ejecutándose, cuándo esperando y, sobre todo, nos permite ver de forma gráfica cuándo estamos viviendo una situación de deadlock u otros tipos de bloqueos entre hilos.

En el hilo principal también podemos ver las pausas que realiza JFR para la recopilación de estadísticas.

6. Conclusiones

Java Mission Control es una herramienta estupenda para monitorizar y hacer profiling de aplicaciones que puedan ser mejoradas desde el punto de vista del rendimiento. Se suma al ya extenso abanico de herramientas de este tipo, siendo sus puntos fuertes el que esté incluido en el JDK desde la versión 1.7.40 y la buena presentación de los resultados y facilidad de uso en operaciones complejas, así como el mínimo overhead producido por el efecto del observador.

Java Flight Recorder es un gran añadido a JMC que, aunque no introduzca muchas funcionalidades revolucionarias en el mundo del profiling de aplicaciones Java, su facilidad de uso, personalización y su aproximación a las métricas más complicadas de tal manera que sean medianamente fáciles de entender tanto a iniciados como a expertos en estos temas.

7. Referencias