not - Rastreando un problema de pérdida de memoria/recolección de basura en Java

memory leak java code

Question

Este es un problema que he intentado rastrear durante un par de meses. Tengo una aplicación java 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 rastrear.

Antecedentes: en el cuadro 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 y cuatro núcleos de 64 bits con 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
• Spring / WebMVC 2.5
• Hibernate 3
• Cuarzo 1.6.1
• DBCP 1.2.1
• Mysql 5.0.45
• Ehcache 1.5.0
• (y, por supuesto, una gran cantidad de otras dependencias, especialmente las bibliotecas jakarta-commons)

Lo más cerca que puedo llegar a reproducir el problema es una máquina de 32 bits con menos requisitos de memoria. De eso tengo control. Lo probé hasta la muerte con JProfiler y solucioné muchos problemas de rendimiento (problemas de sincronización, consultas previas a la compilación / almacenamiento en memoria caché, reducción del grupo de hilos y eliminación de la precarga innecesaria de hibernación, y sobrecalentamiento de "caché" durante el procesamiento).

En cada caso, el generador de perfiles los mostró como una gran cantidad de recursos por una razón u otra, y que estos ya no eran los cerdos de recursos primarios una vez que los cambios entraron.

El problema: la JVM parece ignorar completamente las configuraciones de uso de memoria, llena toda la memoria y deja de responder. Este es un problema para el cliente, que espera una encuesta regular (5 minutos y un minuto de reintento), así como para nuestros equipos de operaciones, a quienes constantemente se les notifica que una casilla no responde y deben reiniciarla. No hay nada más significativo que se ejecute en esta caja.

El problema parece ser la recolección de basura. Estamos utilizando el recopilador ConcurrentMarkSweep (como se señaló anteriormente) porque el recopilador STW original estaba causando 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, comienza a arrojar fallas cms, y vuelve al colector stop-the-world original, que luego parece no recogerse correctamente.

Sin embargo, al ejecutar jprofiler, el botón "Ejecutar GC" parece limpiar bien la memoria 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 hotspots probados no parece funcionar, estoy se fue con el vudú de sintonizar la Colección de basura a ciegas.

Lo que he intentado:

• Perfilado y fijación de puntos de acceso.
• Uso de recolectores de basura STW, Parallel y CMS.
• Corriendo con tamaños de montón mínimo / máximo en incrementos de 1 / 2,2 / 4,4 / 5,6 / 6.
• Correr con espacio permgen en incrementos de 256M hasta 1Gb.
• Muchas combinaciones de las anteriores.
• También consulté 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 o ejemplos de _which_ tuning parámetros para usar en una situación como esta.
• También (sin éxito) he probado jprofiler en modo fuera de línea, conectando con jconsole, visualvm, pero parece que no encuentro nada que interperte mis datos de registro de gc.

Desafortunadamente, el problema también aparece de forma esporádica, parece ser impredecible, puede durar días o incluso una semana sin problemas, o puede fallar 40 veces al día, y lo único que parece captar consistentemente es esa recolección de basura está actuando.

¿Alguien puede dar algún consejo sobre:
a) ¿Por qué una JVM está utilizando 8 gigas físicas y 2 gb de espacio de intercambio cuando está configurado para un máximo de 6?
b) Una referencia a la sintonización 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 las referencias no reclamadas, pero me refiero a nivel de biblioteca / marco, o algo más inherenet en las estructuras de datos, como los hashmaps).

Gracias por cualquier información que pueda proporcionar.

EDITAR
Emil H:
1) Sí, mi clúster de desarrollo es un espejo de los datos de producción, hasta el servidor de medios. La principal diferencia es la 32 / 64bit 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) Existe algún código heredado que se basa en JaxB, pero al reordenar los trabajos para tratar de evitar conflictos de programación, generalmente eliminé esa ejecución ya que se ejecuta una vez al día. El analizador primario usa consultas XPath que invocan el paquete java.xml.xpath. Esta fue la fuente de algunos puntos de acceso, en uno de ellos las consultas no estaban precompiladas, y dos de las referencias estaban en cadenas codificadas. Creé un caché de enhebrado (hashmap) y factoré las referencias a las consultas xpath para que fueran cadenas estáticas finales, lo que redujo significativamente el consumo de recursos. La consulta todavía es una gran parte del procesamiento, pero debería ser porque esa es la principal responsabilidad de la aplicación.

3) Una nota adicional, el otro consumidor primario son las operaciones de imagen de JAI (reprocesamiento de imágenes desde un feed). No estoy familiarizado con las bibliotecas gráficas de Java, pero por lo que he descubierto, no son particularmente defectuosas.

(gracias por las respuestas hasta ahora, amigos!)

ACTUALIZAR:
Pude conectarme a la instancia de producción con VisualVM, pero había desactivado la opción de visualización de GC / ejecución de GC (aunque podía verla localmente). Lo interesante: la asignación de almacenamiento dinámico de la máquina virtual obedece a JAVA_OPTS, y la pila real asignada está cómodamente asentada en 1-1.5 gigas, y no parece estar goteando, pero la monitorización a nivel de caja todavía muestra un patrón de fuga, pero es no reflejado en la monitorización de VM. No hay nada más corriendo en esta caja, así que estoy perplejo.

Answer 1

"Desafortunadamente, el problema también aparece de forma esporádica, parece ser impredecible, puede durar días o incluso una semana sin problemas, o puede fallar 40 veces al día, y lo único que parece atrapar consistentemente es que la recolección de basura está actuando mal ".

Parece que esto está relacionado con un caso de uso que se ejecuta hasta 40 veces al día y luego deja de funcionar durante días. Espero que no solo sigas solo los síntomas. Esto debe ser algo que pueda restringir al rastrear las acciones de los actores de la aplicación (usuarios, trabajos, servicios).

Si esto ocurre por importaciones de XML, debe comparar los datos XML del día de los 40 fallos con los datos, que se importan en un día sin fallas. Tal vez sea algún tipo de problema lógico, que no encuentres dentro de tu código, solo.

Answer 2

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

Además, me parece que visualgc , ahora incluido con JDK 6, es una excelente manera de ver lo que está sucediendo en la memoria. Muestra los espacios eden, generational y perm y el comportamiento transitorio del GC maravillosamente. Todo lo que necesitas es el PID del proceso. Quizás eso ayude mientras trabajas en JProfile.

¿Y los aspectos de trazabilidad / registro de Spring? Tal vez puedas escribir un aspecto simple, aplicarlo de manera declarativa y hacer el perfilador de un pobre de esa manera.

Answer 3

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

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

Monitoreo y administración usando JMX

Y luego adjuntar con JConsole, VisualVM ?

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

En caso afirmativo, entonces podría analizar el volcado del montón para detectar fugas con JProfiler (que ya tiene), jhat , VisualVM, http://www.eclipse.org/mat/ . También compare los volcados de pila que podrían ayudar a encontrar fugas / patrones.

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

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

Answer 4

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.

Intenté con jmap mientras el proceso estaba actuando, pero esto usualmente causaba que el jvm siguiera más, y tenía que ejecutarlo con --force. Esto dio lugar a volcados de almacenamiento dinámico que parecían faltar una gran cantidad de datos, o al menos faltaban las referencias entre ellos. Para el análisis, probé jhat, que presenta una gran cantidad de datos pero no mucha información sobre cómo 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 era principalmente clases relacionadas con tomcat.

El problema era que jmap no estaba informando sobre el estado real de la aplicación, y solo estaba captando las clases en el cierre, que era principalmente clases de tomcat.

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

Usando esto, analicé los registros lentos de consulta y algunos problemas de rendimiento no relacionados. Intenté cargar extra-perezoso ( http://docs.jboss.org/hibernate/core/3.3/reference/en/html/performance.html ), así como reemplazar algunas operaciones de hibernación con consultas jdbc directas (principalmente donde estaba tratando de cargar y operar en colecciones grandes -los reemplazos jdbc solo funcionaban directamente en las tablas de combinación), y reemplazó algunas otras consultas ineficientes que mysql estaba registrando.

Estos pasos mejoraron las piezas del rendimiento del frontend, 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.5 GB) que mostró con precisión el estado de la aplicación. Irónicamente, el archivo era tan grande que jhat no podía analizarlo, incluso 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 que un único hilo de cuarzo estaba ocupando 4.5GB de los 6GB de Heap, y la mayoría de eso era un Hibernate StatefulPersistenceContext ( 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 (yo había desactivado el segundo nivel y los cachés de consulta respaldados por EHCache).

Esta clase se usa para habilitar la mayoría de las funciones de hibernación, por lo que no se puede deshabilitar directamente (se puede solucionar directamente, pero la primavera no admite la sesión sin estado), y me sorprendería mucho si esto tuviera una fuga de memoria importante en un producto maduro. Entonces, ¿por qué estaba goteando ahora?

Bueno, era una combinación de cosas: el grupo de hilos de cuarzo ejemplifica ciertas cosas siendo threadLocal, Spring estaba inyectando una fábrica de sesiones, que estaba creando una sesión al comienzo del ciclo de vida de los hilos de cuarzo, que luego se reutilizaba para ejecutar el varios trabajos de cuarzo que usaron la sesión de hibernación. Hibernate estaba almacenando en la memoria caché en la sesión, que es su comportamiento esperado.

El problema entonces es que el grupo de subprocesos nunca soltó la sesión, por lo que hibernate permaneció residente y mantuvo el caché para el ciclo de vida de la sesión. Dado que esto estaba usando el soporte de plantillas de Spring Hibernate, no hubo un uso explícito de las sesiones (estamos usando un dao -> manager -> driver -> quartz-job hierarchy, el dao se inyecta con hibernate configs hasta la primavera, por lo que las operaciones son hecho directamente en las plantillas).

Así que la sesión nunca se cerraba, hibernación mantenía referencias a los objetos de la memoria caché, por lo que nunca se recolectaban basura, por lo que cada vez que se ejecutaba un nuevo trabajo, simplemente seguía llenando el caché local del hilo, por lo que ni siquiera cualquier intercambio entre los diferentes trabajos. Además, dado que se trata de un trabajo de escritura intensiva (muy poca lectura), el caché se desperdiciaba en su mayoría, por lo que los objetos seguían siendo creados.

La solución: crea un método dao que explícitamente llama 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 supervisión, errores de memoria o reinicios.

Gracias por la ayuda de todos en esto, era un error bastante complicado de localizar, 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.

Answer 5

Buscaría directamente ByteBuffer asignado.

Del javadoc.

Se puede crear un búfer de byte directo invocando el método de fábrica allocateDirect de esta clase. Los almacenamientos intermedios devueltos por este método suelen tener costos de asignación y desasignación algo mayores que los almacenamientos intermedios no directos. El contenido de los almacenamientos intermedios directos puede residir fuera del montón normal recogido 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 almacenamientos intermedios directos solo cuando producen una ganancia medible en el rendimiento del programa.

Tal vez el código de Tomcat usa esto para E / S; configurar Tomcat para usar 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 de probar.

Answer 6

Parece que se está escapando algo que no es montón, 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. Como informa haber conectado con VisualVM, debería poder ver la cantidad de clases cargadas, si hay un aumento continuo de las clases cargadas (importante, visualvm también muestra la cantidad total de clases cargadas, está bien si esto sube pero la cantidad de clases cargadas debería estabilizarse después de un cierto tiempo).

Si se convierte en 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 comenzar un pequeño script en el servidor que invoque repetidamente (¿cada hora?):

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

jmap con ese parámetro generará una visió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: me refiero a la identificación del proceso y debe ser una marca de tiempo generada para distinguir los archivos)

Una vez que identificó ciertas clases como cargadas y no descargadas, puede averiguar mentalmente dónde podrían generarse, de lo contrario, puede usar jhat para analizar volcados generados con jmap -dump. Lo guardaré para una futura actualización si necesita la información.

Answer 7

Tuve el mismo problema, con un par de diferencias ...

Mi tecnología es la siguiente:

Grails 2.2.4

tomcat7

quartz-plugin 1.0

Uso dos fuentes de datos en mi aplicación. Esa es una particularidad determinante para las causas de errores.

Otra cosa a considerar es el plugin de cuarzo, inyectar sesión de hibernación en hilos de cuarzo, como dice @liam, y los hilos de cuarzo aún 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 tiene un oyente que inicia y destruye las 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 realizada con AggregatePersistenceContextInterceptor pasa a HibernatePersistence, sin ninguna modificación o tratamiento.

Cuando llamamos a init() en HibernatePersistenceContextInterceptor , incrementa la variable estática a continuación

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

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

Hasta aquí solo explico el cenario.

El problema viene ahora ...

Cuando termina mi trabajo de cuarzo, el complemento llama al oyente para que descargue y destruya las sesiones de hibernación, como se puede ver en el código fuente de SessionBinderJobListener .

La descarga ocurre perfectamente, pero la destrucción no, porque HibernatePersistence , hace una validación antes de cerrar la sesión de hibernación ... Examina nestingCount para ver si el valor es más gratificante 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 fuga de memoria. Los hilos de cuarzo aún están vivos con todos los objetos usados ​​en la sesión, porque impide que el ORM cierre la sesión, debido a un error causado porque tengo dos fuentes de datos.

Para resolver eso, personalizo el oyente, invoco clear before destroy y call destroy dos veces (una para cada fuente de datos). Asegurándome de que mi sesión estaba clara y destruida, y si la destrucción falla, al menos estaba claro.