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

Yes, that's the number of minor and major collections together. There were 28 minor GCs and 3 major GCs.

Minor collections trigger those lines you cite. If there aren't timestamps, I don't think you can force them short of modifying the JVM. However it's my understanding that "Application time" is the time that the app has run since the last minor collection (pause), so that might give you what you want. It is, I believe, at least a time delta since the last output.

Answer 2

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.

Answer 3

You will have timestamps corresponding to each entry.

A sample from my server log shows

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

The 124951.831 and 125015.262 in this case is the number of seconds elapsed since the JVM has started.

124951.831 corresponds to 34 hours, 42 mins, 31 sec of JVM uptime.

125015.262 corresponds to 34 hours, 43 mins, 35 sec of JVM uptime.

You'll have to correlate this backwards to the server start time, and thus you can get timestamps.

The difference is important (125015 - 124951) shows that the Minor GC kicked in after 64 seconds (in my case).

Are these timestamp lines missing in your log?