Librerías comunes en Tomcat 8. Caso real: SoapUI mocks

Bueno, ya era hora de actualizar un poco esto, y además con material que ya tenía generado de antes, pero entre unas cosas y otras lo fui dejando...

En esta entrada analizaremos un problema relacionado con la inestabilidad de un servidor Tomcat 8, concretamente, indisponibilidades y caídas provocadas por falta de memoria (OutOfMemoryError).

Este Tomcat se utiliza exclusivamente para desplegar 'mock services' generados con la herramienta SoapUI, permitiendo simular el funcionamiento de diferentes sistemas de backend (que a su vez son invocados por servicios de integración que corren en un ESB). El número de servicios mock a desplegar es notablemente alto y los recursos de la máquina son limitados, por lo que asignar más memoria a la JVM no parece una solución sostenible.

Como medida alternativa, inicialmente se opta por configurar el servidor para compartir las librerías comunes entre diferentes despliegues, ahorrando así memoria, aunque como consecuencia de esto se observará posteriormente un comportamiento anómalo que habrá de diagnosticar y corregir.

El problema: alto consumo de memoria

Debido a un alto número de servicios mock desplegados se observa que con el tiempo Tomcat se degrada y deja de responder, apareciendo la causa claramente reflejada en los logs (java.lang.OutOfMemoryError: Java heap space y java.lang.OutOfMemoryError: Metaspace).

Inicialmente se opta por incrementar el tamaño de heap y metaspace reservados para la JVM, con el fin de mitigar o retrasar estos problemas. Se configura además un GC de tipo CMS con settings estándar y se activa el volcado a fichero de las trazas de log del GC con el fin de analizarlas después.

Para ello en Tomcat 8 se crea/modifica el fichero $CATALINA_HOME/bin/setenv.sh con una configuración similar a ésta, realizándose después algunas pruebas con diferentes tamaños de heap y metaspace (no merece la pena entrar a detallar los números):

export CATALINA_OPTS="$CATALINA_OPTS -Xms2048m -Xmx4096m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=1024m -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/tomcatGC-$(date +%Y%m%d_%H%M).log"

Más info sobre los parámetros de arranque de la JVM:

El fichero de trazas generado por el GC tiene esta pinta:


Estos ficheros pueden ser analizados con diferentes herramientas, y la interpretación de los resultados da para mucho por lo que no los trataremos aquí. Yo he utilizado este servicio online: http://gceasy.io/




Comparto aquí uno de los reports generados (a ver lo que dura el enlace):

Tras diferentes pruebas se observa que el problema no desaparece por más memoria que le dedicamos a la JVM (llegando al límite de la RAM disponible en la máquina). A medida que se despliegan e inicializan más servicios mock el problema se reproduce antes (llega a haber unos 85 servicios mock desplegados, que se van inicializando con el primer uso).
Está claro que reservar más memoria no será una solución sostenible. Aumentar la RAM de la máquina o levantar más de un Tomcat (en otros puertos o incluso en máquinas diferentes) tampoco parece lo más idóneo por el coste que conlleva.

¿Alternativas?

La solución inicial: uso compartido de librerías comunes

Pues resulta que en este Tomcat tenemos desplegados como aplicaciones exclusivamente los .war generados con la herramienta SoapUI correspondientes a los diferentes servicios mock, en el directorio $CATALINA_HOME/webapps:



Y si comparamos su contenido observamos que son muy similares, salvo el web.xml y el proyecto SoapUI (fichero *-soapui-project.xml). Todos los .war contienen unos 50 MB en librerías (*.jar) en la ruta WEB-INF/lib:



¿Cómo maneja Tomcat las clases que contienen estas librerías? Si carga una copia independiente para cada aplicación desplegada, ¿es posible 'sacar factor común' y conseguir que las cargue una sola vez? ¿Es necesario además 'retocar' de algún modo los .war que genera la herramienta SoapUI, o podemos evitar ese paso y utilizarlos tal cual?

Empezamos por leer la documentación de Tomcat 8 para entender un poco cómo funciona el asunto:

Como primera conclusión tenemos: el comportamiento por defecto de Tomcat es buscar primero entre las clases y librerías presentes en cada aplicación individual, antes de buscar en el repositorio común (excepto clases base de la JVM y propias de Tomcat, que tienen prioridad sobre las anteriores). Es decir, se confirma que cada aplicación desplegada, cada mock service, tiene cargada su propia copia de las clases presentes en las diferentes librerías. Si todos son prácticamente iguales esto supone un derroche considerable.

¿Es posible cambiar este comportamiento e invertir el orden de prioridad de carga? Claro que sí:

Vemos que es posible modificar algunos aspectos del componente 'Loader' asociado a un 'contexto', y que es posible modificar el 'contexto' por defecto (además de particularizarlo para cada aplicación de forma individual) según se indica aquí:
Teniendo todo esto en cuenta, procedemos a configurar Tomcat para modificar el comportamiento de los class-loader, dando prioridad a las clases presentes en las librerías comunes sobre las clases y librerías propias de cada aplicación individual.

Para ello modificamos el fichero $CATALINA_HOME/conf/context.xml y añadimos lo siguiente dentro de la etiqueta <Context>:

    <Loader delegate="true" />
   

Una vez modificada la configuración procedemos a incluir las librerías presentes en los .war (WEB-INF/lib/*.jar) en el directorio de librerías comunes de Tomcat, $CATALINA_HOME/lib, para que las encuentre allí antes que en el repositorio propio de cada aplicación:



Reiniciamos Tomcat para que se apliquen los cambios en la configuración.

Durante el arranque se vuelcan al log algunos mensajes relacionados con la carga de clases que no parecen indicar ningún problema serio. Posteriormente comprobamos que las diferentes aplicaciones (mock services) se inicializan correctamente y dan servicio.

Echamos mano de un entorno de integración continua (Jenkins/Maven) que nos permite lanzar de forma automática algunas pruebas sobre los servicios que hacen uso de esos mock services, generando carga de trabajo en Tomcat.

Tras algún tiempo de uso comprobamos que Tomcat es ahora estable, sus tiempos de respuesta son mejores y las caídas por falta de memoria ya no se producen, incluso con un gran número de servicios mock desplegados. La herramienta GC Easy nos indica que presenta un buen estado de salud y que el uso de memoria es mucho más contenido de lo que era anteriormente con los mismos servicios desplegados:



Parece que hemos dado con la tecla: ahora Tomcat sólo mantiene en memoria una copia de todas esas clases que SoapUI usa internamente para ejecutar los servicios mock, independientemente de cuántos tengamos desplegados en el servidor. Con esta configuración será posible desplegar muchos más mocks sin provocar caídas ni ser necesario reservar tanta memoria para Tomcat. Tampoco ha sido necesario modificar los .war para eliminar las librerías ya que son ignoradas por el classloader al encontrarlas primero en el repositorio común.

Pero aún queda una sorpresa desagradable que no descubriremos hasta más adelante...

La consecuencia indeseada: errores en ejecución

Tras varios días de "ausencia" por mi parte dedicándome a otros menesteres, y habiendo dado por buena la solución anterior sin haber vigilado de cerca el asunto, me encontré lo siguiente en el dashboard de la solución de monitorización con la que andaba trasteando entonces (Kibana, parte de ELK stack):



Durante los últimos días los servicios del bus (que invocan a los mock services de Tomcat) habían devuelto fallo aproximadamente 2 de cada 3 veces. Llevaba algunas semanas monitorizando un entorno de laboratorio en el que lo habitual era más de un 85% de OK (los KO se deben a que algunos servicios mock devuelven adrede alguna que otra respuesta errónea en forma de SoapFault). Había pasado a tener un 60% de KOs.

Utilizo Kibana para visualizar cómo ha evolucionado este indicador a lo largo del tiempo y me encuentro con esto:




Parece que algo se torció al modificar la configuración de Tomcat. Son datos agregados de todos los servicios desplegados, pero el cambio de tendencia es claro a partir de ese momento. Por el camino veo que Tomcat sigue a su rollo sin estresarse, con un uso de memoria contenido y sin caídas, y compruebo que si vuelvo a la configuración original, la tasa de errores vuelve a los valores habituales. Pero no quiero rendirme aún ni descartar el uso compartido de librerías, así que cambio de nuevo el setting y me dispongo a investigar qué está pasando.

Durante varios días no puedo dedicarle tiempo al asunto, así que lo dejo evolucionar y únicamente lanzo algunas ejecuciones automatizadas para generar actividad en el entorno y recopilar info más adelante.

Para ello me apoyo en el entorno de integración continua desde donde puedo lanzar pruebas de carga de forma concurrente sobre los diferentes servicios que hacen uso de los mock desplegados en Tomcat. Mientras lanzo las pruebas, vigilo los logs de Tomcat (nada concluyente) y los logs de estas pruebas de carga, que tienen esta pinta:


Dispongo de varios servicios desplegados y puedo lanzar varias pruebas a la vez, dentro de la modesta capacidad que tienen las máquinas del laboratorio:


Finalmente me puedo poner con ello en serio, y veo algo relevante:


Un servicio simple, que siempre funciona y devuelve OK (salvo catástrofe), en un momento dado empieza a fallar (HTTP error 500 como respuesta). Justo en el momento en que se ha comenzado a ejecutar otra prueba en paralelo. Ya tengo una pista.

Sigo durante un buen rato lanzando pruebas en paralelo mientras redespliego algunos mock, identifico servicios que presentan conflictos entre sí, etc. Me apoyo también en la consola 'manager' de Tomcat para 'recargar' servicios que han fallado:

Compruebo que un mock service que empieza a fallar no es que haya entrado en un estado 'inconsistente' porque sí, sino porque otro que presenta conflicto con él es inicializado, recargado, etc. Una vez falla no vuelve a funcionar por sí solo, pero si lo vuelvo a recargar, desplegar, reinicio Tomcat... el servicio vuelve a funcionar, causando a veces que falle otro diferente.

Llego a la conclusión entonces de que la implementación de SoapUI para levantar servicios mock guarda alguna información de 'estado' en alguna 'variable global', tal vez algún atributo estático de alguna clase, etc. y al ser éstas compartidas por todas las aplicaciones, al inicializarse se produce algún tipo de conflicto en concurrencia de tipo 'el último que llega machaca lo que había antes'. Eso explicaría que cuando recargo una aplicación desde el manager, el servicio que estaba fallando vuelve a funcionar bien, y otros que estaban funcionando bien comienzan a fallar:



Me planteo la hipótesis de que dicha 'variable global' sea un atributo de alguna clase presente en la propia librería de SoapUI (soapui-5.3.0.jar) y no en cualquier otra librería de terceros de propósito más general (manejo de XML/JSON, serializer, log4j...).

Para comprobarlo elimino del directorio de librerías compartidas únicamente dicha librería (soapui-5.3.0.jar) y reinicio Tomcat.

Lanzo de nuevo unas cuantas pruebas concurrentes para generar carga de trabajo en Tomcat e intercalar invocaciones a diferentes mocks para reproducir el error. Revisando los logs observo que todo parece ir bien y que los servicios no quedan en un estado inconsistente. Lo dejo evolucionar algún tiempo y posteriormente veo un cambio claro de tendencia en la monitorización:



Parece que la hipótesis se confirma. Tomcat continúa configurado para usar primero las librerías comunes, pero la librería de SoapUI ya no es una de ellas, y para cada aplicación (mock service) carga su propia copia, pues sólo la encuentra en cada repositorio de clases individual (en cada .war). Ya no hay conflictos entre aplicaciones desplegadas.

Esto conlleva un ligero incremento en el uso de memoria de Tomcat, proporcional al número de mock services desplegados, pero bastante menor al de la configuración inicial, sin caídas ni OutOfMemoryError, y el funcionamiento anómalo detectado parece haber desaparecido.

Habrá que seguir monitorizando el funcionamiento y el consumo de memoria por si aparecen más problemas, pero esto tiene ya mejor pinta.

Las conclusiones: compartir librerías con cuidado y probando bien

Como hemos visto, el uso compartido de librerías no es una solución universal aplicable a todos los casos de falta de memoria debido a los efectos no deseados que puede conllevar. En este caso al tener un Tomcat dedicado exclusivamente a una tarea concreta (despliegue de mock services) hemos podido aplicar esta estrategia con algunas precauciones.

Como corolario podríamos decir que el escenario común donde poder aplicar algo parecido, y siempre 'con cuidao', sería aquél en el que tenemos que desplegar en el mismo servidor diferentes aplicaciones que 'comparten muchas librerías' (por estar desarrolladas bajo un mismo framework, por ejemplo).

Y nada más por el momento. Este tema no volvió a dar problemas y no fue necesario volver a intervenir.

¡Hasta otra!



Versiones de software

 - Apache Tomcat 8.0.43
 - JDK 1.8.0_102
 - SoapUI 5.3.0
 - Linux 2.6.32-504.el6.x86_64

Comentarios

Entradas populares de este blog

Desacoplamiento mediante colas de mensajes

Arquitectura híbrida cloud / on-premise