GC aclaración de salida

Question

estoy ejecutando una aplicación Java con los siguientes valores:
-XX: + CMSParallelRemarkEnabled
-XX: + UseConcMarkSweepGC
-XX: + UseParNewGC
-XX: + PrintGCApplicationStoppedTime
-XX : + PrintGCApplicationConcurrentTime
-XX: + PrintGCDetails
-XX: + PrintGCTimeStamps
-XX: + PrintGCDateStamps
-XX: + PrintHeapAtGC
-XX: + PrintTenuringDistribution

No estoy seguro de cómo interpretar los registros de gc relacionados (a continuación). En particular:

• montón después de invocaciones GC = 31 (total 3): ¿significa esto que había 31 menores GC, GC y 3 de su capacidad?

• Qué desencadena las varias líneas consecutivas de tiempo total para la que las hebras de la aplicación fueron detenidos y Aplicación Tiempo de? ¿Es posible obtener las marcas de tiempo asociadas con cada una de estas líneas?

registros GC:

 
Total time for which application threads were stopped: 0.0046910 seconds 
Application time: 0.7946670 seconds 
Total time for which application threads were stopped: 0.0002900 seconds 
Application time: 1.0153640 seconds 
Total time for which application threads were stopped: 0.0002780 seconds 
Application time: 1.0161890 seconds 
Total time for which application threads were stopped: 0.0002760 seconds 
Application time: 1.0145990 seconds 
Total time for which application threads were stopped: 0.0002950 seconds 
Application time: 0.9999800 seconds 
Total time for which application threads were stopped: 0.0002770 seconds 
Application time: 1.0151640 seconds 
Total time for which application threads were stopped: 0.0002730 seconds 
Application time: 0.9996590 seconds 
Total time for which application threads were stopped: 0.0002880 seconds 
Application time: 0.9624290 seconds 

{Heap before GC invocations=30 (full 3): 
par new generation total 131008K, used 130944K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000) 
    eden space 130944K, 100% used [0x00000000eac00000, 0x00000000f2be0000, 0x00000000f2be0000) 
    from space 64K, 0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000) 
    to space 64K, 0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000) 
concurrent mark-sweep generation total 131072K, used 48348K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000) 
concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000) 

2010-05-11T09:30:13.888+0100: 384.955: [GC 384.955: [ParNew 
Desired survivor size 32768 bytes, new threshold 0 (max 0) 
: 130944K->0K(131008K), 0.0052470 secs] 179292K->48549K(262080K), 0.0053030 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

Heap after GC invocations=31 (full 3): 
par new generation total 131008K, used 0K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000) 
    eden space 130944K, 0% used [0x00000000eac00000, 0x00000000eac00000, 0x00000000f2be0000) 
    from space 64K, 0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000) 
    to space 64K, 0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000) 
concurrent mark-sweep generation total 131072K, used 48549K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000) 
concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000) 
} 

Total time for which application threads were stopped: 0.0056410 seconds 
Application time: 0.0475220 seconds 
Total time for which application threads were stopped: 0.0001800 seconds 
Application time: 1.0174830 seconds 
Total time for which application threads were stopped: 0.0003820 seconds 
Application time: 1.0126350 seconds 
Total time for which application threads were stopped: 0.0002750 seconds 
Application time: 1.0155910 seconds 
Total time for which application threads were stopped: 0.0002680 seconds 
Application time: 1.0155580 seconds 
Total time for which application threads were stopped: 0.0002880 seconds 
Application time: 1.0155480 seconds 
Total time for which application threads were stopped: 0.0002970 seconds 
Application time: 0.9896810 seconds 

Answer 1

esas líneas sin marcas de tiempo no son eventos de gc, registran cuándo ocurren los puntos de seguridad y cuánto duraron. Pre 6u21 son algo poco confiables.

Answer 2

Sí, ese es el número de colecciones menores y mayores juntos. Hubo 28 GC menores y 3 GC principales.

Las colecciones secundarias desencadenan esas líneas que cita. Si no hay marcas de tiempo, no creo que puedas forzarlas a no modificar la JVM. Sin embargo, entiendo que "Tiempo de aplicación" es el tiempo que la aplicación se ejecutó desde la última recopilación menor (pausa), por lo que podría darle lo que desea. Es, creo, al menos un delta de tiempo desde la última salida.

Answer 3

Tendrá marcas de tiempo correspondientes a cada entrada.

Una muestra de mi registro del servidor muestra

124951.831: [GC 1915727K->1295438K(1994752K), 0.1964641 secs] 
Total time for which application threads were stopped: 0.1983187 seconds 
125015.262: [GC 1909838K->1302111K(1994752K), 0.2037094 secs] 
Total time for which application threads were stopped: 0.2055489 seconds 

El 124.951,831 y 125.015,262 en este caso es ha comenzado el número de segundos transcurridos desde la JVM.

124951.831 corresponde a 34 horas, 42 minutos, 31 segundos de tiempo de actividad de JVM.

125015.262 corresponde a 34 horas, 43 minutos, 35 segundos de tiempo de actividad de JVM.

Deberá correlacionar esto al revés con la hora de inicio del servidor, y así podrá obtener marcas de tiempo.

La diferencia es importante (125015 - 124951) muestra que el GC menor se inició después de 64 segundos (en mi caso).

¿Faltan estas líneas de marca de tiempo en su registro?