java - recoleccion - Experimentando largas demoras en la recolección de basura, ¿por qué?

recoleccion de residuos caba

Question

Me cuesta mucho lidiar con un problema de recolección de basura de Java e interpretar los registros.

Mi aplicación requiere que ningún GC tarde más de 2 segundos, e idealmente menos de 100 ms.

Basado en algunos consejos previos estoy probando las siguientes opciones de línea de comando:

 java -XX:MaxGCPauseMillis=100 -XX:NewRatio=9 -XX:+UseConcMarkSweepGC  -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -server -Xmx9g -Xms9g 

La aplicación tiene una gran cantidad de objetos almacenados a largo plazo, que se guardan en un ConcurrentLinkedHashMap. Veo pausas largas ocasionales, en el peor de los casos, hasta 10 segundos (¡esta es la segunda más reciente de los registros del GC a continuación)!

Aquí está algo de la salida que estoy obteniendo:

16938.968: [GC 16938.968: [ParNew: 153343K->17022K(153344K), 7.8608580 secs] 6184328K->6122510K(9420160K) icms_dc=7 , 7.8614100 secs] [Times: user=0.63 sys=0.01, real=7.86 secs] 
16947.087: [GC 16947.087: [ParNew: 153342K->17022K(153344K), 7.2604030 secs] 6258830K->6198642K(9420160K) icms_dc=7 , 7.2609780 secs] [Times: user=0.44 sys=0.00, real=7.27 secs] 
16954.614: [GC 16954.614: [ParNew: 153342K->17024K(153344K), 8.4307620 secs] 6334962K->6274625K(9420160K) icms_dc=7 , 8.4313150 secs] [Times: user=0.62 sys=0.01, real=8.43 secs] 
16963.310: [GC 16963.310: [ParNew: 153344K->17023K(153344K), 6.2588760 secs] 6410945K->6350748K(9420160K) icms_dc=7 , 6.2594290 secs] [Times: user=0.48 sys=0.01, real=6.25 secs] 
16969.834: [GC 16969.834: [ParNew: 153343K->17022K(153344K), 6.0274280 secs] 6487068K->6425868K(9420160K) icms_dc=7 , 6.0279830 secs] [Times: user=0.50 sys=0.01, real=6.03 secs] 
16976.122: [GC 16976.123: [ParNew: 153342K->17022K(153344K), 11.7774620 secs] 6562188K->6503030K(9420160K) icms_dc=7 , 11.7780180 secs] [Times: user=0.43 sys=0.04, real=11.78 secs] 
16988.164: [GC 16988.164: [ParNew: 153342K->17024K(153344K), 10.9477920 secs] 6639350K->6579928K(9420160K) icms_dc=7 , 10.9483440 secs] [Times: user=0.37 sys=0.02, real=10.95 secs] 
16999.371: [GC 16999.372: [ParNew: 153344K->17023K(153344K), 9.8828360 secs] 6716248K->6655886K(9420160K) icms_dc=7 , 9.8833940 secs] [Times: user=0.42 sys=0.01, real=9.88 secs] 
17009.509: [GC 17009.509: [ParNew: 153343K->17023K(153344K), 5.0699960 secs] 6792206K->6727987K(9420160K) icms_dc=7 , 5.0705660 secs] [Times: user=0.55 sys=0.01, real=5.07 secs] 
17014.838: [GC 17014.838: [ParNew: 153343K->17023K(153344K), 6.6411750 secs] 6864307K->6790974K(9420160K) icms_dc=7 , 6.6417400 secs] [Times: user=0.37 sys=0.01, real=6.63 secs] 
17021.735: [GC 17021.735: [ParNew: 153343K->17024K(153344K), 8.0545970 secs] 6927294K->6856409K(9420160K) icms_dc=7 , 8.0551790 secs] [Times: user=0.34 sys=0.03, real=8.05 secs] 
17030.052: [GC 17030.053: [ParNew: 153344K->17023K(153344K), 7.9756730 secs] 6992729K->6922569K(9420160K) icms_dc=7 , 7.9762530 secs] [Times: user=0.34 sys=0.01, real=7.98 secs] 
17038.398: [GC 17038.398: [ParNew: 153343K->17022K(153344K), 12.9613300 secs] 7058889K->6990725K(9420160K) icms_dc=7 , 12.9618850 secs] [Times: user=0.39 sys=0.01, real=12.96 secs] 
17051.630: [GC 17051.630: [ParNew: 153342K->17022K(153344K), 6.8942910 secs] 7127045K->7059607K(9420160K) icms_dc=7 , 6.8948380 secs] [Times: user=0.56 sys=0.02, real=6.89 secs] 
17058.798: [GC 17058.798: [ParNew: 153342K->17024K(153344K), 10.0262190 secs] 7195927K->7126351K(9420160K) icms_dc=7 , 10.0267860 secs] [Times: user=0.37 sys=0.01, real=10.02 secs] 
17069.096: [GC 17069.096: [ParNew: 153344K->17023K(153344K), 10.0419500 secs] 7262671K->7195002K(9420160K) icms_dc=7 , 10.0425020 secs] [Times: user=0.40 sys=0.02, real=10.04 secs] 
17079.410: [GC 17079.410: [ParNew: 153343K->17022K(153344K), 13.5389040 secs] 7331322K->7264275K(9420160K) icms_dc=7 , 13.5394610 secs] [Times: user=0.30 sys=0.01, real=13.54 secs] 
17093.223: [GC 17093.224: [ParNew: 153342K->17023K(153344K), 10.5909450 secs] 7400595K->7330446K(9420160K) icms_dc=7 , 10.5915060 secs] [Times: user=0.33 sys=0.00, real=10.58 secs] 
17104.083: [GC 17104.084: [ParNew: 153343K->17024K(153344K), 5.8420210 secs] 7466766K->7392173K(9420160K) icms_dc=7 , 5.8425920 secs] [Times: user=0.57 sys=0.00, real=5.84 secs] 

Pasé horas revisando varias páginas web que describen la sintonización de Java GC, pero ninguna me ha dado la capacidad de interpretar los registros anteriores y presentar un curso de acción. Cualquier consejo específico basado en los registros que he proporcionado sería muy apreciado.

Actualización: por una pregunta a continuación:

La máquina tiene 16G de RAM, aquí está la información de arriba: Mem: 15483904k total, 15280084k usado, 203820k libre, búferes de 155684k Intercambio: 2031608k total, 1347240k usado, 684368k libre, 3304044k en caché

Es una ejecución diferente, pero aquí está el resultado superior actual para el proceso:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  1016 sanity   17   0 10.2g 6.5g 9464 S    1 44.2  10:24.32 java                      

Actualización 2: algunos registros más detallados, esto parecía que causó un retraso de 400 ms:

{Heap before GC invocations=1331 (full 1):
 par new generation   total 153344K, used 153343K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K, 100% used [0x00002aaaae200000, 0x00002aaab6720000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab77c0000, 0x00002aaab885fff0, 0x00002aaab8860000)
  to   space 17024K,   0% used [0x00002aaab6720000, 0x00002aaab6720000, 0x00002aaab77c0000)
 concurrent mark-sweep generation total 7169664K, used 4258496K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
484.738: [GC 484.738: [ParNew: 153343K->17022K(153344K), 0.3950480 secs] 4411840K->4341689K(7323008K), 0.3954820 secs] [Times: user=0.49 sys=0.07, real=0.40 secs] 
Heap after GC invocations=1332 (full 1):
 par new generation   total 153344K, used 17022K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K,   0% used [0x00002aaaae200000, 0x00002aaaae200000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab6720000, 0x00002aaab77bfb68, 0x00002aaab77c0000)
  to   space 17024K,   0% used [0x00002aaab77c0000, 0x00002aaab77c0000, 0x00002aaab8860000)
 concurrent mark-sweep generation total 7169664K, used 4324666K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
}

Answer 1

¿Has ejecutado tu aplicación a través de un generador de perfiles para ver que lo que crees que está sucediendo con respecto a memeory es lo que realmente está sucediendo?

Una cosa que hago cuando estoy investigando esto es utilizar el perfil de Netbeans (aunque cualquier generador de perfiles debería dárselo) es mirar los bytes activos (la asignación de memoria) y ver si los que tienen una gran cantidad de bytes asignados y asignados objectd son lo que estoy esperando y vienen de donde espero.

También es probable que pueda usar el generador de perfiles para ver el efecto que está teniendo su ajuste, ejecutar la aplicación sin ningún tipo de argumentos, y luego agregar sus argumentos de ajuste y ejecutarlo de nuevo y ver qué está sucediendo con la memoria.

Answer 2

¿Has visto esto?

http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html

también, eche un vistazo a ...

http://java.sun.com/javase/6/docs/technotes/guides/visualvm/index.html

Answer 3

¿Tal vez el límite de rendimiento de 200 ms es demasiado estricto y necesita administrar la recolección de basura por su cuenta? ¿Has probado esto con un límite mayor?

Answer 4

Desde los tiempos, parece que el GC en realidad no se ejecuta todo el tiempo (vea los tiempos del usuario), así que la mayoría de las veces, está esperando.

Solo una loca suposición: ¿no cambia? ¿Cuánta memoria tiene la máquina? ¿Cuánto obtiene el proceso de Java (tamaño del conjunto residente)?

Editar: ¿por qué está esperando?

Mira esto (de tu transcripción)

[Times: user=0.39 sys=0.01, real=12.96 secs]

Esto significa que (creo que desde el principio hasta el final de la GC), pasaron 12 (casi 13) segundos. De estos 13 segundos, .39 se gastó ejecutándose en modo de usuario, .01 se gastó ejecutándose en modo kernel. Si el método de recopilación de tiempo no está totalmente defectuoso (es decir, los números realmente representan el tiempo de ejecución del proceso / hilo de GC), esto significa al menos 12 segundos de espera.

Answer 5

En general, es difícil ajustar el GC cuando se necesita un montón tan grande.

Dicho esto, la mayor parte del tiempo de suspensión de GC es causado por la copia de memoria de objetos que sobreviven en colecciones de basura jóvenes.

¿Inicializa su ConcurrentLinkedHashMap con todos los objetos persistentes de memoria a la vez? ¿O crece lentamente a medida que la aplicación sigue funcionando? Si es el último, puede ser difícil reducir los tiempos de suspensión de GC ya que hay objetos que siempre sobreviven. Si es el primero, tendrá que dimensionar la generación con el tamaño de sus objetos persistentes + 20% más o menos, y asegurarse de que su generación joven sea lo suficientemente grande como para mantenerse al día con los objetos transitorios que se crean durante el curso de su aplicación.

Answer 6

Puede ser muy difícil de decir sin ver realmente y, en algunos casos, perfilar el código.

¿Has implementado finalize () para cualquiera de tus objetos? Eso causará una gran penalización por GC. También sería interesante ver una prueba con un montón de tal vez 6 Gigs, si obtienes una mejora desproporcionada en el rendimiento, eso indicaría que el GC está agotando la memoria.

Answer 7

Si tiene requisitos de tiempo estrictos, tal vez debería consultar el Sistema en tiempo real de Java .

RTSJ / Java RTS proporciona:

Un conjunto de API, mejoras semánticas de Java VM y modificaciones de capa de JVM a OS que permiten a los desarrolladores de Java razonar correctamente sobre el comportamiento temporal de las aplicaciones Java y controlarlo.

Answer 8

¿Puedes publicar / vincular al código de la implementación de ConcurrentLinkedHashMap? Si esta es la implementación que he publicado, abra un ticket en la página del proyecto para que podamos depurarlo juntos. De lo contrario, conocer los detalles de su implementación ayudaría a determinar dónde podría estar el problema.

Answer 9

¡9 GB de JVM! ¡Nunca antes visto eso! Creo que tus 10 segundos las pausas son bastante normales. mira esto (tal vez ya lo has leído ...)

Answer 10

Resultó que el problema era que el montón se cambiaba a un disco, y el retraso era que el GC de Java tenía que esperar a que se cambiara de nuevo.

Resuelto (principalmente) estableciendo el parámetro "swappiness" de Linux en 0.

Answer 11

Creo que está teniendo este error UseConcMarkSweepGC y NewRatio . Dado que su nuevo espacio no está cerca de ser una décima parte de -Jmx=9G . El error incluye una solución (NewSize en tamaño absoluto).

Otra CMSInitiatingOccupancyFraction que podría ser muy importante para usted es CMSInitiatingOccupancyFraction . Se establece en 92% en java6 y fue 68% en java5. Si el espacio antiguo se hace más grande, el grupo de subprocesos CMS comenzará a hacer su trabajo. Si tiene CPU para gastar, no es peligroso tener un Live Set que esté por encima de la fracción de inicio.

Sería bueno si hubiera incluido las estadísticas del GC después de haber solucionado el problema de la búsqueda de memoria.

Answer 12

para mí, el problema era espacios completos de supervivencia. Como CMS no es comparativo, la basura se promovió directamente a la generación anterior. esto podría ser muy costoso con un montón tan grande. Es necesario aumentar los espacios de Superviviente y MaxTenuringThreshold para evitar la promoción tanto como sea posible.

Saludos, Alex

Answer 13

Creo que su atención podría estar un poco mal dirigida.

Pase un poco de tiempo en un generador de perfiles para encontrar los puntos de acceso más grandes. Si solo hay unos pocos lugares en el código donde se producen la mayoría de las asignaciones, intente utilizar un conjunto de objetos en lugar de construir siempre objetos nuevos.

Las clases de recopilación y StringBuilders son excelentes candidatos para la agrupación. Cuando los devuelva al grupo, llame a los métodos collection.clear () o stringbuilder.setLength (0) para que estén listos para el consumo cuando el próximo llamante desee recuperarlos del grupo.

La mejor manera de sintonizar el GC es creando menos objetos. Hay muchas estrategias para eliminar asignaciones, y la puesta en común es solo una de ellas (aunque es una de mis favoritas).

ACTUALIZACIÓN: Han pasado cinco años desde que escribí esta respuesta, y mi opinión sobre la puesta en común ha cambiado principalmente. Cuando escribí esta respuesta en 2009, con frecuencia podía usar la agrupación de objetos (incluso de objetos simples como StringBuilder) para acelerar los bucles interiores apretados con muchas asignaciones. En estos días, es más difícil encontrar casos en los que el agrupamiento no empeore la situación. Casi nunca uso pools para nada más que hilos o conexiones. Sin embargo, es una buena herramienta para tener a su disposición, incluso si no la usa a menudo.