java - ¿Cómo puedo obtener G1 para imprimir más detalles de registro?

garbage-collection

Question

Estoy probando una API basada en Jetty contra una basada en Netty. Con la única diferencia en el experimento de qué API utilizo (la misma aplicación, los mismos servidores, la misma configuración de memoria, la misma carga, etc.), obtengo pausas más largas de GC con la basada en Netty. Principalmente, las pausas son inferiores a un milisegundo, pero después de unos días de funcionar sin problemas, cada 12-24 horas veré una pausa de 4-6 segundos que no aparece con la API basada en Jetty.

Cada vez que esto sucede, hay muy poca información sobre lo que G1 estaba haciendo que causó la emisión de un STW, tenga en cuenta el segundo mensaje de pausa aquí:

2016-02-23T05:22:27.709+0000: 66360.282: Total time for which application threads were stopped: 0.0319639 seconds, Stopping threads took: 0.0000716 seconds
2016-02-23T05:22:35.642+0000: 66368.215: Total time for which application threads were stopped: 6.9705594 seconds, Stopping threads took: 0.0000737 seconds
2016-02-23T05:22:35.673+0000: 66368.246: Total time for which application threads were stopped: 0.0048374 seconds, Stopping threads took: 0.0040574 seconds 

Mis opciones de GC son:

-XX:+UseG1GC 
-XX:+G1SummarizeConcMark 
-XX:+G1SummarizeRSetStats 
-XX:+PrintAdaptiveSizePolicy 
-XX:+PrintGC 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:+DisableExplicitGC 
-XX:InitialHeapSize=12884901888 
-XX:MaxHeapSize=12884901888 

Y, como referencia, mis opciones de VM son:

-XX:+AlwaysPreTouch 
-XX:+DebugNonSafepoints 
-XX:+FlightRecorder 
-XX:FlightRecorderOptions=stackdepth=500 
-XX:-OmitStackTraceInFastThrow 
-XX:+TrustFinalNonStaticFields 
-XX:+UnlockCommercialFeatures 
-XX:+UnlockDiagnosticVMOptions 
-XX:+UnlockExperimentalVMOptions 
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 

¿Cómo puedo descubrir por qué G1 detuvo el mundo en 2016-02-23T05:22:35.642 ?

Answer 1

No todas las pausas STW (el mecanismo utilizado para activarlas se denomina punto seguro ) son causadas por el GC, use -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 para imprimir otras causas de safepoint.

En segundo lugar, si las pausas son causadas por GC, las líneas que pegó no contienen la causa, pero un bloque adyacente al registro del GC debe contener la causa, algo así como [GC pause (G1 Evacuation Pause) (young), 0.0200285 secs]

Además, es posible que desee controlar la latencia de IO de disco y las marcas de tiempo de coincidencia para pausas de seguridad. Cualquier Sync IO o paginación que ocurra durante los safepoints que va a almacenamiento lento puede bloquear todo el safepoint. Poner logfiles y /tmp en un tmpfs o SSD puede ayudar.

Answer 2

Para agregar algo de cierre a esto: El problema era que esto no era, técnicamente, una pausa de GC; fue una combinación de varios factores:

• AWS acelera IO a lo que ha pagado
• / tmp en Ubuntu por defecto terminó en nuestro volumen de EBS (acelerado)
• la JVM escribe de forma predeterminada en / tmp durante stop-the-world (!)

Otras partes de nuestra aplicación alcanzaron el umbral de aceleración de EBS, y cuando la JVM intentó escribir en / tmp durante una STW, todos los subprocesos de la JVM se pusieron en cola detrás del punto de aceleración AWS.

Parece que la diferencia Netty / Jetty fue una pista falsa.

Necesitamos que nuestra aplicación sobreviva en este tipo de entorno, por lo que nuestra solución fue desactivar este comportamiento de JVM, a costa de perder soporte de varias herramientas de JVM que agregamos:

-XX:+PerfDisableSharedMem

Más información sobre este tema en esta excelente publicación de blog: http://www.evanjones.ca/jvm-mmap-pause.html