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

Answer 2

Most of it is explained in the GC Tuning Guide (which you would do well to read anyway).

The command line option -verbose:gc causes information about the heap and garbage collection to be printed at each collection. For example, here is output from a large server application:

[GC 325407K->83000K(776768K), 0.2300771 secs]
[GC 325816K->83372K(776768K), 0.2454258 secs]
[Full GC 267628K->83769K(776768K), 1.8479984 secs]

Here we see two minor collections followed by one major collection. The numbers before and after the arrow (e.g., 325407K->83000K from the first line) indicate the combined size of live objects before and after garbage collection, respectively. After minor collections the size includes some objects that are garbage (no longer alive) but that cannot be reclaimed. These objects are either contained in the tenured generation, or referenced from the tenured or permanent generations.

The next number in parentheses (e.g., (776768K) again from the first line) is the committed size of the heap: the amount of space usable for java objects without requesting more memory from the operating system. Note that this number does not include one of the survivor spaces, since only one can be used at any given time, and also does not include the permanent generation, which holds metadata used by the virtual machine.

The last item on the line (e.g., 0.2300771 secs) indicates the time taken to perform the collection; in this case approximately a quarter of a second.

The format for the major collection in the third line is similar.

The format of the output produced by -verbose:gc is subject to change in future releases.

I'm not certain why there's a PSYoungGen in yours; did you change the garbage collector?

Answer 3

I just wanted to mention that one can get the detailed GC log with the

-XX:+PrintGCDetails 

parameter. Then you see the PSYoungGen or PSPermGen output like in the answer.

Also -Xloggc:gc.log seems to generate the same output like -verbose:gc but you can specify an output file in the first.

Example usage:

java -Xloggc:./memory.log -XX:+PrintGCDetails Memory

To visualize the data better you can try gcviewer (a more recent version can be found on github).

Take care to write the parameters correctly, I forgot the "+" and my JBoss would not start up, without any error message!