Pausa larga incidental Recolección de basura joven pausa

Question

Ajustamos nuestro GC para pausas mínimas "pare el mundo". Las generaciones Perm y Tenured se comportan bien. Joven funciona bien la mayor parte del tiempo, y las pausas en general no exceda de 500 ms (nota [Tiempos: user = 0.35 = 0.02 sys, reales = 0,06 segs]):

{Heap before GC invocations=11603 (full 60): 
par new generation total 3640320K, used 3325226K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000) 
    eden space 3235840K, 100% used [0x0000000600000000, 0x00000006c5800000, 0x00000006c5800000) 
    from space 404480K, 22% used [0x00000006de300000, 0x00000006e3a4a898, 0x00000006f6e00000) 
    to space 404480K, 0% used [0x00000006c5800000, 0x00000006c5800000, 0x00000006de300000) 
concurrent mark-sweep generation total 4147200K, used 1000363K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000) 
concurrent-mark-sweep perm gen total 196608K, used 133030K [0x00000007f4000000, 0x0000000800000000, 0x0000000800000000) 
2012-07-16T14:36:05.641+0200: 427048.412: [GC 427048.412: [ParNew 
Desired survivor size 207093760 bytes, new threshold 4 (max 4) 
- age 1: 8688880 bytes, 8688880 total 
- age 2: 12432832 bytes, 21121712 total 
- age 3: 18200488 bytes, 39322200 total 
- age 4: 20473336 bytes, 59795536 total 
: 3325226K->75635K(3640320K), 0.0559610 secs] 4325590K->1092271K(7787520K), 0.0562630 secs] [Times: user=0.35 sys=0.02, real=0.06 secs] 
Heap after GC invocations=11604 (full 60): 
par new generation total 3640320K, used 75635K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000) 
    eden space 3235840K, 0% used [0x0000000600000000, 0x0000000600000000, 0x00000006c5800000) 
    from space 404480K, 18% used [0x00000006c5800000, 0x00000006ca1dcf40, 0x00000006de300000) 
    to space 404480K, 0% used [0x00000006de300000, 0x00000006de300000, 0x00000006f6e00000) 
concurrent mark-sweep generation total 4147200K, used 1016635K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000) 
concurrent-mark-sweep perm gen total 196608K, used 133030K [0x00000007f4000000, 0x0000000800000000, 0x0000000800000000) 
} 

Sin embargo, a veces, por lo general una vez al día, tenemos tiempo excepcionalmente largo joven recolección de basura (nota: [tiempos de usuario sys = 0,41 = 0,01, reales = 5,51 seg]):

{Heap before GC invocations=7884 (full 37): 
par new generation total 3640320K, used 3304448K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000) 
    eden space 3235840K, 100% used [0x0000000600000000, 0x00000006c5800000, 0x00000006c5800000) 
    from space 404480K, 16% used [0x00000006c5800000, 0x00000006c9b00370, 0x00000006de300000) 
    to space 404480K, 0% used [0x00000006de300000, 0x00000006de300000, 0x00000006f6e00000) 
concurrent mark-sweep generation total 4147200K, used 1967225K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000) 
concurrent-mark-sweep perm gen total 189100K, used 112825K [0x00000007f4000000, 0x00000007ff8ab000, 0x0000000800000000) 
2012-07-15T01:23:25.474+0200: 293088.245: [GC 293093.636: [ParNew 
Desired survivor size 207093760 bytes, new threshold 4 (max 4) 
- age 1: 30210472 bytes, 30210472 total 
- age 2: 11614600 bytes, 41825072 total 
- age 3: 8591680 bytes, 50416752 total 
- age 4: 7779600 bytes, 58196352 total 
: 3304448K->73854K(3640320K), 0.1158280 secs] 5271674K->2046454K(7787520K), 0.1181990 secs] [Times: user=0.41 sys=0.01, real=5.51 secs] 
Heap after GC invocations=7885 (full 37): 
par new generation total 3640320K, used 73854K [0x0000000600000000, 0x00000006f6e00000, 0x00000006f6e00000) 
    eden space 3235840K, 0% used [0x0000000600000000, 0x0000000600000000, 0x00000006c5800000) 
    from space 404480K, 18% used [0x00000006de300000, 0x00000006e2b1fb40, 0x00000006f6e00000) 
    to space 404480K, 0% used [0x00000006c5800000, 0x00000006c5800000, 0x00000006de300000) 
concurrent mark-sweep generation total 4147200K, used 1972599K [0x00000006f6e00000, 0x00000007f4000000, 0x00000007f4000000) 
concurrent-mark-sweep perm gen total 189100K, used 112825K [0x00000007f4000000, 0x00000007ff8ab000, 0x0000000800000000) 
} 

a continuación se muestra la salida relevante de -gccause jstat:

Timestamp   S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC     
    293083.2 16.96 0.00 96.26 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
    293083.2 16.96 0.00 96.26 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
    293084.2 16.96 0.00 97.69 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
    293085.3 16.96 0.00 98.32 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
    293086.3 16.96 0.00 99.32 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
Timestamp   S0  S1  E  O  P  YGC  YGCT FGC FGCT  GCT LGCC     GCC     
    293087.3 16.96 0.00 99.55 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  No GC    
    293088.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293089.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293090.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293091.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293092.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293093.3 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293084.2 16.96 0.00 100.00 47.44 59.66 7884 772.326 74 10.893 783.219 unknown GCCause  Allocation Failure 
    293094.3 0.00 18.26 6.23 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC    
    293094.6 0.00 18.26 6.71 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC    
    293095.3 0.00 18.26 6.85 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC    
    293095.6 0.00 18.26 6.92 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC    
    293096.2 0.00 18.26 9.84 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC    
    293096.6 0.00 18.26 10.11 47.56 59.66 7885 772.442 74 10.893 783.334 unknown GCCause  No GC 

appe "Allocation Failure" ars como el GC causa en otros lugares también, pero siempre como una sola entrada. Cuando se trata de una secuencia como esta, se asocia a una pausa larga de GC. Busqué fuentes Oracle JVM, y "Allocation Failure" parece una situación bastante natural: Young se ha quedado sin espacio para obtener nuevos datos y es hora de limpiar. Comprobé si había alguna acción inesperada que requiera mucha memoria en el sistema antes de que ocurriera la pausa, pero no encontré nada sospechoso.

Tenga en cuenta que el tiempo de recolección de basura joven no aumenta mucho durante el tiempo de pausa. Mi memoria y el ajuste de GC son los siguientes (configuración de registro omitidas):

-Xms6000m 
-Xmn2950m 
-Xmx6000m 
-XX:MaxPermSize=192m 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC 
-Dsun.rmi.dgc.client.gcInterval=9223372036854775807 
-Dsun.rmi.dgc.server.gcInterval=9223372036854775807 
-XX:CMSInitiatingOccupancyFraction=50 
-XX:+CMSScavengeBeforeRemark 
-XX:+CMSClassUnloadingEnabled 

probado también con 8000m y 12000m montones. Máquinas:

• 8-núcleo con 16 GB de memoria
• 24 núcleos con 50 GB de memoria

Así que mi pregunta básica es: ¿por qué se comporta ParNewGC por cierto de esta manera?

Answer 1

Antes de que se pueda realizar un GC, tiene que llevar cada hilo a un punto seguro (no solo detiene cada hilo inmediatamente). Si lleva mucho tiempo haciendo llamadas JNI o ​​llamadas al sistema, puede tomar mucho tiempo llegar a un punto seguro. Lo que ves en esta situación es una pausa larga, aunque la colección en sí era de una duración normal en el tiempo.