GC output clarification

Question

I'm running a java application with the following settings:
-XX:+CMSParallelRemarkEnabled
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution

I'm not sure how to interpret the related gc logs(below). In particular:

• Heap after GC invocations=31 (full 3): does this mean there were 31 minor GCs, and 3 full GCs ?

• What triggers the several consecutive lines of Total time for which the application threads were stopped and Application Time ? Is it possible to get the time stamps associated with each of these lines ?

GC logs:

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

those lines without timestamps aren't gc events, they record when safepoints occur and how long they lasted for. Pre 6u21 they are somewhat unreliable.