1. Inicio
  2. Pregunta y respuesta
  3. Hung JVM consume 100% CPU

Hung JVM consume 100% CPU

2011-02-03 26 views
10

Tenemos un servidor JAVA ejecutándose en Sun JRE 6u20 en Linux de 32 bits (CentOS). Usamos el hotspot Server con colector CMS con las siguientes opciones (yo sólo he proporcionado los más relevantes):Hung JVM consume 100% CPU

-Xmx896m -Xss128k -XX:NewSize=384M -XX:MaxPermSize=96m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC

A veces, después de correr durante un tiempo, la JVM parece caer en un estado bloqueado, por lo que incluso aunque no hacemos ninguna solicitud a la aplicación, la CPU continúa girando al 100% (tenemos 8 CPU lógicas, por lo que parece que solo una CPU hace el giro). En este estado, la JVM no responde a las señales de SIGHUP (kill -3) y no podemos conectarnos a ella normalmente con jstack. Podemos conectarnos con "jstack -F", pero el resultado es dudoso (podemos ver muchos NullPointerExceptions de JStack aparentemente porque no fue capaz de 'caminar' algunas pilas). Entonces la salida "jstack -F" parece ser inútil.

Sin embargo, hemos ejecutado un volcado de pila de "gdb", y pudimos hacer coincidir la id del hilo que hace girar la CPU (encontramos que usando "arriba" con una vista por hilo - opción "H") una pila de subprocesos que aparece en el resultado del BGF y así es como se ve:

Thread 443 (Thread 0x7e5b90 (LWP 26310)): 
#0 0x0115ebd3 in CompactibleFreeListSpace::block_size(HeapWord const*) const() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#1 0x01160ff9 in CompactibleFreeListSpace::prepare_for_compaction(CompactPoint*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#2 0xc in Generation::prepare_for_compaction(CompactPoint*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#3 0x01229b2c in GenCollectedHeap::prepare_for_compaction()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#4 0x0122a7fc in GenMarkSweep::invoke_at_safepoint(int, ReferenceProcessor*, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#5 0x01186024 in CMSCollector::do_compaction_work(bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#6 0x011859ee in CMSCollector::acquire_control_and_collect(bool, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#7 0x01185705 in ConcurrentMarkSweepGeneration::collect(bool, bool, unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#8 0x01227f53 in GenCollectedHeap::do_collection(bool, bool, unsigned int, bool, int)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#9 0x0115c7b5 in GenCollectorPolicy::satisfy_failed_allocation(unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#10 0x0122859c in GenCollectedHeap::satisfy_failed_allocation(unsigned int, bool)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#11 0x0158a8ce in VM_GenCollectForAllocation::doit()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#12 0x015987e6 in VM_Operation::evaluate()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#13 0x01597c93 in VMThread::evaluate_operation(VM_Operation*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#14 0x01597f0f in VMThread::loop()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#15 0x015979f0 in VMThread::run()() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#16 0x0145c24e in java_start(Thread*)() from /usr/java/jdk1.6.0_20/jre/lib/i386/server/libjvm.so 
#17 0x00ccd46b in start_thread() from /lib/libpthread.so.0 
#18 0x00bc2dbe in clone() from /lib/libc.so.6

parece que un hilo JVM está girando mientras se hace algún trabajo relacionado con la CMS. Hemos comprobado el uso de la memoria en la caja, parece que hay suficiente memoria disponible y el sistema no se está intercambiando. ¿Alguien ha encontrado tal situación? ¿Se ve como un error de JVM?

ACTUALIZACIÓN

que he obtenido alguna información más sobre este problema (que pasó de nuevo en un servidor que ha estado funcionando durante más de 7 días). Cuando la JVM entró en estado "colgado" permaneció así durante 2 horas hasta que el servidor se reinició manualmente. Hemos obtenido un volcado de núcleo del proceso y el registro de gc. También intentamos obtener un volcado dinámico, pero "jmap" falló. Intentamos usar jmap -F, pero luego solo se escribió un archivo de 4Mb antes de que se cancelara el programa con una excepción (algo acerca de la ubicación de memoria no accesible). Hasta ahora, creo que la información más interesante proviene del registro de gc. Parece que el registro de GC se detuvo también (posiblemente en el momento cuando el hilo VM entró en el bucle de longitud):

657501.199: [Full GC (System) 657501.199: [CMS: 400352K->313412K(524288K), 2.4024120 secs] 660634K->313412K(878208K), [CMS Perm : 29455K->29320K(68568K)], 2.4026470 secs] [Times: user=2.39 sys=0.01, real=2.40 secs] 
657513.941: [GC 657513.941: [ParNew: 314624K->13999K(353920K), 0.0228180 secs] 628036K->327412K(878208K), 0.0230510 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
657523.772: [GC 657523.772: [ParNew: 328623K->17110K(353920K), 0.0244910 secs] 642036K->330523K(878208K), 0.0247140 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
657535.473: [GC 657535.473: [ParNew: 331734K->20282K(353920K), 0.0259480 secs] 645147K->333695K(878208K), 0.0261670 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
.... 
.... 
688346.765: [GC [1 CMS-initial-mark: 485248K(524288K)] 515694K(878208K), 0.0343730 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
688346.800: [CMS-concurrent-mark-start] 
688347.964: [CMS-concurrent-mark: 1.083/1.164 secs] [Times: user=2.52 sys=0.09, real=1.16 secs] 
688347.964: [CMS-concurrent-preclean-start] 
688347.969: [CMS-concurrent-preclean: 0.004/0.005 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
688347.969: [CMS-concurrent-abortable-preclean-start] 
CMS: abort preclean due to time 688352.986: [CMS-concurrent-abortable-preclean: 2.351/5.017 secs] [Times: user=3.83 sys=0.38, real=5.01 secs] 
688352.987: [GC[YG occupancy: 297806 K (353920 K)]688352.987: [Rescan (parallel) , 0.1815250 secs]688353.169: [weak refs processing, 0.0312660 secs] [1 CMS-remark: 485248K(524288K)] 783055K(878208K), 0.2131580 secs] [Times: user=1.13 sys 
=0.00, real=0.22 secs] 
688353.201: [CMS-concurrent-sweep-start] 
688353.903: [CMS-concurrent-sweep: 0.660/0.702 secs] [Times: user=0.91 sys=0.07, real=0.70 secs] 
688353.903: [CMS-concurrent-reset-start] 
688353.912: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
688354.243: [GC 688354.243: [ParNew: 344928K->30151K(353920K), 0.0305020 secs] 681955K->368044K(878208K), 0.0308880 secs] [Times: user=0.15 sys=0.00, real=0.03 secs] 
.... 
.... 
688943.029: [GC 688943.029: [ParNew: 336531K->17143K(353920K), 0.0237360 secs] 813250K->494327K(878208K), 0.0241260 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
688950.620: [GC 688950.620: [ParNew: 331767K->22442K(353920K), 0.0344110 secs] 808951K->499996K(878208K), 0.0347690 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
688956.596: [GC 688956.596: [ParNew: 337064K->37809K(353920K), 0.0488170 secs] 814618K->515896K(878208K), 0.0491550 secs] [Times: user=0.18 sys=0.04, real=0.05 secs] 
688961.470: [GC 688961.471: [ParNew (promotion failed): 352433K->332183K(353920K), 0.1862520 secs]688961.657: [CMS

Sospecho que este problema tiene algo que ver con la última línea en el registro (I' he añadido algunos "...." para omitir algunas líneas que no fueron interesantes). El hecho de que el servidor permaneció en estado colgado durante 2 horas (probablemente intentando GC y compactando la generación anterior) me parece bastante extraño. Además, el registro de gc se detiene de repente con ese mensaje y ya no se imprime nada más, probablemente porque el subproceso de VM entra en una especie de bucle infinito (o algo que lleva más de 2 horas).

Fuente

2011-02-03 Bogdan

+1

Si está ejecutando en condiciones de memoria baja que no es imposible de observar. Pero actualizo la VM, hubo algunas correcciones grandes de GC en u21/22, iirc. También MaxPermSize = 96m es muy bajo, no sé qué ejecutar. – bestsss

+0

Estoy bastante seguro de que la VM no se está ejecutando con poca memoria. Desde el registro de GC Cada vez que hay un GC completo, el OldGen vuelve a tener un promedio de 370Mb, lo que significa que hay aproximadamente un 27% de espacio libre en él. La generación joven (384Mb) está prácticamente vacía en cada limpieza. Entonces creo que hay mucha memoria. El problema parece ocurrir justo antes de que se ejecute el GC completo (como se puede ver en los registros) cuando el OldGen está casi lleno y el recopilador YoungGen no puede promocionar algunos objetos. Probablemente, la VM se da cuenta de que OldGen está demasiado fragmentado, por lo que desencadena una compactación (que dura más de 2 horas). – Bogdan

+0

Observación de un patrón similar con el servidor JRE 6u26 en Windows Server 2008. Falló la promoción ParNe seguida de ese fragmento de una entrada de colección CMS: << 911188.231: [GC 911188.231: [ParNew (promoción fallida): 750602K-> 753650K (811008K), 3.7030115 segundos] 911191.934: [CMS >> La antigua generación tenía 161582K disponible en ese punto, que es comparable a los niveles en los que se desencadenaron las colecciones de CMS previamente en la ejecución. ¿Te preguntas si alguna vez has tenido más información sobre tu problema, Bogdan? – Brant

Respuesta

2

Parece un problema de sintonización del GC, posiblemente desencadenado por una pérdida de memoria. Sugiero que agregue el parámetro de JVM que active el registro de GC, y vea si eso le da alguna información.

¿Se ve como un error de JVM?

No es para mí.

Cuando se agota el espacio en el montón (por ejemplo, como resultado de una fuga de almacenamiento) es común ver que el GC se ejecuta con más frecuencia y utiliza un porcentaje cada vez mayor de la CPU.Hay algunos parámetros de JVM que puede configurar para evitar esto, pero tienen el efecto de hacer que su JVM se incline antes con un OOME. (Esto puede sonar extraño, pero en muchos casos esto es algo bueno porque reduce el tiempo hasta que se reinicie el sistema y pueda volver a funcionar normalmente).

Fuente

2011-02-03 10:15:15

+1

Rara vez he visto a una JVM sin respuesta con un solo subproceso, una alta utilización de CPU ser algo más que el recolector de basura en estado de pánico. El registro de recolección de basura solo le proporcionará la confirmación del comportamiento del recopilador y una indicación del patrón de utilización del montón, para determinar la causa por la que necesitará un volcado de pila y analizarlo con una herramienta como Eclipse MAT (he perdido la cuenta de la cantidad de veces que utilicé un volcado dinámico para encontrar un problema de estado de aplicación o pila difícil, realmente son invaluables). –

+0

En realidad, el registro de GC se habilitó en ese momento (lo tenemos activado de manera predeterminada), pero desafortunadamente el archivo gc.log se sobrescribió cuando se reinició la aplicación. Nos ocuparemos de no eliminarlo la próxima vez que esto ocurra. Intenté generar un volcado dinámico del archivo central, pero no logré hacerlo porque jmap se queja de que no se puede conectar al archivo central (estoy bastante seguro de haber especificado el ejecutable correcto - jsvc). ¡Estoy de acuerdo contigo, Eclipse MAT es oro puro! ;-) – Bogdan

+0

De acuerdo con esto: http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html#cms.oom la JVM debería arrojar un error OOM en algún momento si puede progresa En nuestro caso, la JVM se colgó durante más de 10 minutos y no se lanzó ninguna OOM. ¿No es extraño que kill -3 no active un volcado de hilo extraño? ¿O es el hilo VM que mencioné anteriormente el responsable de tirar las stacktraces en la consola y dado que estaba tan ocupado con el GC-ing no lo hizo? – Bogdan

Cuestiones relacionadas

 Cuestiones relacionadas