Rastreando un problema de fuga de memoria / recolección de basura en Java

Este es un problema que he estado tratando de localizar durante un par de meses. Tengo una aplicación Java en ejecución que procesa feeds xml y almacena el resultado en una base de datos. Ha habido problemas de recursos intermitentes que son muy difíciles de localizar.

Antecedentes: en la caja de producción (donde el problema es más notorio), no tengo un acceso particularmente bueno a la caja y no he podido ejecutar Jprofiler. Esa caja es una máquina de 64 bits de cuatro núcleos y 8 GB que ejecuta centos 5.2, tomcat6 y java 1.6.0.11. Comienza con estos java-opts

JAVA_OPTS="-server -Xmx5g -Xms4g -Xss256k -XX:MaxPermSize=256m -XX:+PrintGCDetails -
XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -XX:+UseParNewGC"

La pila de tecnología es la siguiente:

• Centos de 64 bits 5.2
• Java 6u11
• Tomcat 6
• Primavera / WebMVC 2.5
• Hibernar 3
• Cuarzo 1.6.1
• DBCP 1.2.1
• Mysql 5.0.45
• Ehcache 1.5.0
• (y, por supuesto, una serie de otras dependencias, en particular las bibliotecas jakarta-commons)

Lo más cerca que puedo estar de reproducir el problema es una máquina de 32 bits con menores requisitos de memoria. Sobre eso tengo control. Lo probé hasta la muerte con JProfiler y solucioné muchos problemas de rendimiento (problemas de sincronización, precompilación / almacenamiento en caché de consultas xpath, reducción de la agrupación de subprocesos y eliminación de la búsqueda previa de hibernación innecesaria y "calentamiento de caché" excesivo durante el procesamiento).

En cada caso, el generador de perfiles mostró que estos consumían grandes cantidades de recursos por una razón u otra, y que ya no eran los acaparadores de recursos primarios una vez que se introdujeron los cambios.

El problema: La JVM parece ignorar por completo la configuración de uso de la memoria, llena toda la memoria y deja de responder. Este es un problema para el cliente final, que espera una encuesta periódica (5 minutos y reintento de 1 minuto), así como para nuestros equipos de operaciones, a quienes se les notifica constantemente que una caja no responde y tienen que reiniciarla. No hay nada más significativo en ejecución en esta caja.

El problema parece ser la recolección de basura. Estamos utilizando el recopilador ConcurrentMarkSweep (como se indicó anteriormente) porque el recopilador STW original estaba provocando tiempos de espera de JDBC y se volvió cada vez más lento. Los registros muestran que a medida que aumenta el uso de la memoria, eso comienza a generar fallas de cms y regresa al colector original de stop-the-world, que luego parece no recopilar correctamente.

Sin embargo, al ejecutar jprofiler, el botón "Ejecutar GC" parece limpiar la memoria muy bien en lugar de mostrar una huella creciente, pero como no puedo conectar jprofiler directamente a la caja de producción, y la resolución de puntos de acceso probados no parece estar funcionando, estoy Se fue con el vudú de ajustar a ciegas Garbage Collection.

Lo que he probado:

• Perfilado y fijación de puntos calientes.
• Utilizando recolectores de basura STW, Parallel y CMS.
• Ejecutando con tamaños de montón mínimo / máximo en incrementos de 1 / 2,2 / 4,4 / 5,6 / 6.
• Se ejecuta con espacio permgen en incrementos de 256 M hasta 1 Gb.
• Muchas combinaciones de las anteriores.
• También he consultado la JVM [referencia de ajuste] (http://java.sun.com/javase/technologies/hotspot/gc/gc_tuning_6.html), pero no puedo encontrar nada que explique este comportamiento ni ningún ejemplo de _which_ tuning parámetros para usar en una situación como esta.
• También probé (sin éxito) jprofiler en modo fuera de línea, conectándome con jconsole, visualvm, pero parece que no puedo encontrar nada que interpere mis datos de registro de gc.

Desafortunadamente, el problema también aparece esporádicamente, parece ser impredecible, puede funcionar durante días o incluso una semana sin tener ningún problema, o puede fallar 40 veces al día, y lo único que puedo detectar consistentemente es esa recolección de basura está actuando mal.

¿Alguien puede dar algún consejo sobre:
a) Por qué una JVM está usando 8 gigas físicas y 2 gb de espacio de intercambio cuando está configurada para un máximo de menos de 6.
b) Una referencia al ajuste de GC que realmente explica o da ejemplos razonables de cuándo y con qué tipo de configuración usar las colecciones avanzadas.
c) Una referencia a las fugas de memoria de Java más comunes (entiendo referencias no reclamadas, pero me refiero a nivel de biblioteca / marco, o algo más inherente en estructuras de datos, como hashmaps).

Gracias por todos y cada uno de los conocimientos que puede proporcionar.

EDITAR
Emil H:
1) Sí, mi grupo de desarrollo es un espejo de los datos de producción, hasta el servidor de medios. La principal diferencia es el 32/64 bits y la cantidad de RAM disponible, que no puedo replicar muy fácilmente, pero el código, las consultas y la configuración son idénticos.

2) Hay algún código heredado que se basa en JaxB, pero al reordenar los trabajos para tratar de evitar conflictos de programación, generalmente elimino esa ejecución, ya que se ejecuta una vez al día. El analizador principal utiliza consultas XPath que llaman al paquete java.xml.xpath. Esta fue la fuente de algunos puntos de acceso, por un lado, las consultas no se estaban compilando previamente, y dos, las referencias a ellas estaban en cadenas codificadas. Creé un caché seguro para subprocesos (hashmap) y factoricé las referencias a las consultas de xpath para que fueran cadenas estáticas finales, lo que redujo significativamente el consumo de recursos. La consulta sigue siendo una gran parte del procesamiento, pero debería serlo porque esa es la principal responsabilidad de la aplicación.

3) Una nota adicional, el otro consumidor principal son las operaciones de imágenes de JAI (reprocesamiento de imágenes de una fuente). No estoy familiarizado con las bibliotecas gráficas de Java, pero por lo que he encontrado, no tienen fugas particularmente.

(¡Gracias por las respuestas hasta ahora, amigos!)

ACTUALIZACIÓN:
pude conectarme a la instancia de producción con VisualVM, pero había deshabilitado la opción GC visualization / run-GC (aunque pude verlo localmente). Lo interesante: la asignación de pila de la VM obedece a JAVA_OPTS, y la pila asignada real se sienta cómodamente en 1-1.5 gigas, y no parece tener fugas, pero el monitoreo de nivel de caja todavía muestra un patrón de fugas, pero es no se refleja en el monitoreo de VM. No hay nada más ejecutándose en esta caja, así que estoy perplejo.

Bueno, finalmente encontré el problema que estaba causando esto, y estoy publicando una respuesta detallada en caso de que alguien más tenga estos problemas.

Probé con jmap mientras el proceso funcionaba, pero esto generalmente causaba que el jvm se cuelgue aún más, y tendría que ejecutarlo con --force. Esto dio como resultado volcados de pila que parecían faltar muchos datos, o al menos faltar las referencias entre ellos. Para el análisis, probé jhat, que presenta muchos datos pero no muchos en la forma de interpretarlos. En segundo lugar, probé la herramienta de análisis de memoria basada en eclipse ( http://www.eclipse.org/mat/ ), que mostró que el montón eran principalmente clases relacionadas con tomcat.

El problema era que jmap no informaba el estado real de la aplicación y solo detectaba las clases al apagar, que eran principalmente clases de tomcat.

Intenté unas cuantas veces más y noté que había algunos recuentos muy altos de objetos modelo (en realidad, 2-3 veces más de los que se marcaron como públicos en la base de datos).

Usando esto, analicé los registros lentos de consultas y algunos problemas de rendimiento no relacionados. Intenté la carga extra-perezosa ( http://docs.jboss.org/hibernate/core/3.3/reference/en/html/performance.html ), así como también reemplacé algunas operaciones de hibernación con consultas jdbc directas (principalmente donde estaba lidiando con la carga y operación en colecciones grandes (los reemplazos de jdbc simplemente funcionaron directamente en las tablas de unión) y reemplazaron algunas otras consultas ineficientes que mysql estaba registrando.

Estos pasos mejoraron partes del rendimiento de la interfaz, pero aún no abordaron el problema de la fuga, la aplicación aún era inestable y actuaba de manera impredecible.

Finalmente, encontré la opción: -XX: + HeapDumpOnOutOfMemoryError. Esto finalmente produjo un archivo hprof muy grande (~ 6.5GB) que mostraba con precisión el estado de la aplicación. Irónicamente, el archivo era tan grande que no pudo analizarlo, ni siquiera en una caja con 16 GB de RAM. Afortunadamente, MAT pudo producir algunos gráficos atractivos y mostró algunos datos mejores.

Esta vez, lo que sobresalió fue un solo hilo de cuarzo que ocupaba 4.5GB de los 6GB de montón, y la mayoría de eso fue un StatefulPersistenceContext hibernado ( https://www.hibernate.org/hib_docs/v3/api/org/hibernate /engine/StatefulPersistenceContext.html ). Esta clase es utilizada por hibernación internamente como su caché principal (había deshabilitado el segundo nivel y los cachés de consulta respaldados por EHCache).

Esta clase se usa para habilitar la mayoría de las características de hibernación, por lo que no se puede deshabilitar directamente (puede solucionarlo directamente, pero Spring no admite sesiones sin estado), y me sorprendería mucho si esto tuviera tal pérdida importante de memoria en un producto maduro. Entonces, ¿por qué estaba goteando ahora?

Bueno, fue una combinación de cosas: el grupo de subprocesos de cuarzo crea una instancia con ciertas cosas que son threadLocal, Spring estaba inyectando una fábrica de sesiones, que estaba creando una sesión al comienzo del ciclo de vida de los subprocesos de cuarzo, que luego se reutilizaba para ejecutar el varios trabajos de cuarzo que utilizaron la sesión de hibernación. Hibernate luego estaba almacenando en caché en la sesión, que es su comportamiento esperado.

El problema entonces es que el grupo de subprocesos nunca liberaba la sesión, por lo que Hibernate permanecía residente y mantenía el caché durante el ciclo de vida de la sesión. Dado que esto estaba usando el soporte de la plantilla de hibernación de springs, no hubo un uso explícito de las sesiones (estamos usando un dao -> administrador -> controlador -> jerarquía de trabajo de cuarzo, el dao se inyecta con configuraciones de hibernación a través de Spring, por lo que las operaciones son hecho directamente en las plantillas).

Entonces, la sesión nunca se cerraba, hibernate mantenía referencias a los objetos de la caché, por lo que nunca se recolectaban basura, por lo que cada vez que se ejecutaba un nuevo trabajo, simplemente seguía llenando la caché local del hilo, por lo que ni siquiera había cualquier intercambio entre los diferentes trabajos. Además, dado que este es un trabajo de escritura intensiva (muy poca lectura), la caché se desperdició en su mayoría, por lo que los objetos se siguieron creando.

La solución: cree un método dao que llame explícitamente a session.flush () y session.clear (), e invoque ese método al comienzo de cada trabajo.

La aplicación se ha estado ejecutando durante unos días sin problemas de monitoreo, errores de memoria o reinicios.

Gracias por la ayuda de todos en esto, fue un error bastante complicado de rastrear, ya que todo estaba haciendo exactamente lo que se suponía que debía hacer, pero al final, un método de 3 líneas logró solucionar todos los problemas.

¿Puede ejecutar la caja de producción con JMX habilitado?

-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=<port>
...

Supervisión y gestión mediante JMX

Y luego adjuntar con JConsole, VisualVM ?

¿Está bien hacer un volcado de pila con jmap? ?

En caso afirmativo, puede analizar el volcado de pila en busca de fugas con JProfiler (ya lo tiene), jhat , VisualVM, Eclipse MAT . También compare los volcados de pila que podrían ayudar a encontrar fugas / patrones.

Y como mencionaste jakarta-commons. Hay un problema al usar jakarta-commons-logging relacionado con mantener el cargador de clases. Para una buena lectura de ese cheque

Un día en la vida de un cazador de fugas de memoria (release(Classloader) )

Parece que la memoria que no sea el montón se está escapando, mencionas que el montón se mantiene estable. Un candidato clásico es permgen (generación permanente) que consta de 2 cosas: objetos de clase cargados y cadenas internas. Dado que informa que se ha conectado con VisualVM, debería poder ver la cantidad de clases cargadas, si hay un aumento continuo de las clases cargadas clases (importante, visualvm también muestra la cantidad total de clases cargadas, está bien si esto aumenta, pero la cantidad de clases cargadas debería estabilizarse después de un cierto tiempo).

Si resulta ser una fuga de permgen, la depuración se vuelve más complicada ya que las herramientas para el análisis de permgen son bastante deficientes en comparación con el montón. Su mejor opción es iniciar un pequeño script en el servidor que invoca repetidamente (¿cada hora?):

jmap -permstat <pid> > somefile<timestamp>.txt

jmap con ese parámetro generará una descripción general de las clases cargadas junto con una estimación de su tamaño en bytes, este informe puede ayudarlo a identificar si ciertas clases no se descargan. (nota: con me refiero a la identificación del proceso y debería haber una marca de tiempo generada para distinguir los archivos)

Una vez que haya identificado ciertas clases como cargadas y no descargadas, puede averiguar mentalmente dónde se pueden generar; de lo contrario, puede usar jhat para analizar los volcados generados con jmap -dump. Lo guardaré para una futura actualización en caso de que necesite la información.

Buscaría ByteBuffer asignado directamente.

Desde el javadoc.

Se puede crear un búfer de bytes directo invocando el método de fábrica allocateDirect de esta clase. Los búferes devueltos por este método suelen tener costos de asignación y desasignación algo más altos que los búferes no directos. El contenido de los búferes directos puede residir fuera del montón normal de recolección de basura, por lo que su impacto en la huella de memoria de una aplicación puede no ser obvio. Por lo tanto, se recomienda que los búferes directos se asignen principalmente para búferes grandes y de larga duración que estén sujetos a las operaciones de E / S nativas del sistema subyacente. En general, es mejor asignar búferes directos solo cuando producen una ganancia medible en el rendimiento del programa.

Quizás el código de Tomcat usa esto para E / S; configurar Tomcat para utilizar un conector diferente.

De lo contrario, podría tener un hilo que ejecute periódicamente System.gc (). "-XX: + ExplicitGCInvokesConcurrent" podría ser una opción interesante para probar.

¿Alguna JAXB? Encuentro que JAXB es un rellenador de espacio permanente.

Además, encuentro que visualgc , ahora incluido con JDK 6, es una excelente manera de ver lo que está pasando en la memoria. Muestra los espacios edén, generacional y permanente y el comportamiento transitorio de la CG maravillosamente. Todo lo que necesita es el PID del proceso. Quizás eso te ayude mientras trabajas en JProfile.

¿Y qué hay de los aspectos de rastreo / registro de Spring? Tal vez puedas escribir un aspecto simple, aplicarlo declarativamente y hacer un perfil de hombre pobre de esa manera.

"Desafortunadamente, el problema también aparece esporádicamente, parece impredecible, puede funcionar durante días o incluso una semana sin tener ningún problema, o puede fallar 40 veces al día, y lo único que puedo detectar consistentemente es que la recolección de basura está funcionando mal ".

Parece que esto está vinculado a un caso de uso que se ejecuta hasta 40 veces al día y luego ya no durante días. Espero que no solo rastree solo los síntomas. Esto debe ser algo que pueda reducir rastreando las acciones de los actores de la aplicación (usuarios, trabajos, servicios).

Si esto sucede mediante importaciones XML, debe comparar los datos XML del día de 40 bloqueos con los datos que se importan en un día de bloqueo cero. Tal vez sea algún tipo de problema lógico, que no encuentra solo dentro de su código.

Tuve el mismo problema, con un par de diferencias.

Mi tecnología es la siguiente:

griales 2.2.4

tomcat7

complemento de cuarzo 1.0

Utilizo dos fuentes de datos en mi aplicación. Ese es un determinante de particularidad para las causas de los errores.

Otra cosa a considerar es que el plugin de cuarzo, inyecta la sesión de hibernación en hilos de cuarzo, como dice @liam, y los hilos de cuarzo siguen vivos, hasta que termine la aplicación.

Mi problema fue un error en el ORM de Grails combinado con la forma en que el complemento maneja la sesión y mis dos fuentes de datos.

El complemento Quartz tenía un oyente para iniciar y destruir sesiones de hibernación

public class SessionBinderJobListener extends JobListenerSupport {

    public static final String NAME = "sessionBinderListener";

    private PersistenceContextInterceptor persistenceInterceptor;

    public String getName() {
        return NAME;
    }

    public PersistenceContextInterceptor getPersistenceInterceptor() {
        return persistenceInterceptor;
    }

    public void setPersistenceInterceptor(PersistenceContextInterceptor persistenceInterceptor) {
        this.persistenceInterceptor = persistenceInterceptor;
    }

    public void jobToBeExecuted(JobExecutionContext context) {
        if (persistenceInterceptor != null) {
            persistenceInterceptor.init();
        }
    }

    public void jobWasExecuted(JobExecutionContext context, JobExecutionException exception) {
        if (persistenceInterceptor != null) {
            persistenceInterceptor.flush();
            persistenceInterceptor.destroy();
        }
    }
}

En mi caso, persistenceInterceptor instancias AggregatePersistenceContextInterceptor, y tenía una lista de HibernatePersistenceContextInterceptor. Uno para cada fuente de datos.

Cada operación se hace con AggregatePersistenceContextInterceptorsu paso a HibernatePersistence, sin modificaciones ni tratamientos.

Cuando llamados de init()sobre HibernatePersistenceContextInterceptorque incrementa la variable estática por debajo

private static ThreadLocal<Integer> nestingCount = new ThreadLocal<Integer>();

No conozco el propósito de ese recuento estático. Solo sé que se ha incrementado dos veces, una por fuente de datos, debido a laAggregatePersistence implementación.

Hasta aquí solo explico el cenario.

El problema viene ahora ...

Cuando finaliza mi trabajo de cuarzo, el complemento llama al oyente para eliminar y destruir las sesiones de hibernación, como puede ver en el código fuente de SessionBinderJobListener .

La descarga ocurre perfectamente, pero la destrucción no, porque HibernatePersistence, haga una validación antes de cerrar la sesión de hibernación ... ExaminanestingCount para ver si el valor es mayor que 1. Si la respuesta es sí, no cierra la sesión.

Simplificando lo que hizo Hibernate:

if(--nestingCount.getValue() > 0)
    do nothing;
else
    close the session;

Esa es la base de mi pérdida de memoria. Los hilos de cuarzo siguen vivos con todos los objetos utilizados en la sesión, porque los grails ORM no cierran la sesión, debido a un error causado porque tengo dos fuentes de datos.

Para resolver eso, personalizo el oyente, para llamar a borrar antes de destruir y llamar a destruir dos veces (una para cada fuente de datos). Asegurándome de que mi sesión fuera clara y destruida, y si la destrucción falla, él estaba claro al menos.