logging - Java Garbage Collection Log messages

Question

I have configured java to dump garbage collection information into the logs (verbose GC). I am unsure of what the garbage collection entries in the logs mean. A sample of these entries are posted below. I've searched around on Google and have not found solid explanations.

I have some reasonable guesses, but I'm looking for answers which provide strict definitions of what the numbers in the entries mean, backed up by credible sources. An automatic +1 to all answers which cite sun documentation. My questions are:

1. What does PSYoungGen refer to? I assume it has something to do with the previous (younger?) generation, but what exactly?
2. What is the difference between the second triplet of numbers and the first?
3. Why is a name(PSYoungGen) specified for the first triplet of numbers but not the second?
4. What does each number (memory size) in the triplet mean. For example in 109884K->14201K(139904K), is the memory before GC 109884k and then it is reduced to 14201K. How is the third number relevant? Why would we require a second set of numbers?

8109.128: [GC [PSYoungGen: 109884K->14201K(139904K)] 691015K->595332K(1119040K), 0.0454530 secs]

8112.111: [GC [PSYoungGen: 126649K->15528K(142336K)] 707780K->605892K(1121472K), 0.0934560 secs]

8112.802: [GC [PSYoungGen: 130344K->3732K(118592K)] 720708K->607895K(1097728K), 0.0682690 secs]

Answer 1

1. PSYoungGen refers to the garbage collector in use for the minor collection. PS stands for Parallel Scavenge.
2. The first set of numbers are the before/after sizes of the young generation and the second set are for the entire heap. (Diagnosing a Garbage Collection problem details the format)
3. The name indicates the generation and collector in question, the second set are for the entire heap.

An example of an associated full GC also shows the collectors used for the old and permanent generations:

3.757: [Full GC [PSYoungGen: 2672K->0K(35584K)] 
            [ParOldGen: 3225K->5735K(43712K)] 5898K->5735K(79296K) 
            [PSPermGen: 13533K->13516K(27584K)], 0.0860402 secs]

Finally, breaking down one line of your example log output:

8109.128: [GC [PSYoungGen: 109884K->14201K(139904K)] 691015K->595332K(1119040K), 0.0454530 secs]

• 107Mb used before GC, 14Mb used after GC, max young generation size 137Mb
• 675Mb heap used before GC, 581Mb heap used after GC, 1Gb max heap size
• minor GC occurred 8109.128 seconds since the start of the JVM and took 0.04 seconds