GC Log Message Format for Serial Collector

Java GC Tutorials - Herong's Tutorial Examples

∟GC Log Message Format for Serial Collector

This section provides explanations on GC log messages generated from the Serial Collector.

The first step to help us understand how Serial Collector works is to understand the GC log messages generated from the Serial Collector.

Let's capture some GC log messages with my sample program, GarbageCollection.java:

herong> java -XX:+UseSerialGC -Xlog:gc,gc+heap=info GarbageCollection

[0.019s][info][gc] Using Serial
...

Okay. We got our first GC log message at 0.019 seconds after the application have started. It confirms that the JVM is using the Serial GC.

Continue with additional output in the console:

...
Step/TotalMemory/FreeMemory/UsedMemory:
1   127729664   107555136   20174528
2   127729664   105882632   21847032
...
14   127729664   92701256   35028408
[0.906s][info][gc,heap] GC(0) DefNew: 34207K->4288K(38720K)
[0.906s][info][gc,heap] GC(0) Tenured: 0K->13758K(86016K)
[0.906s][info][gc     ] GC(0) Pause Young (Allocation Failure)
   33M->17M(121M) 28.706ms
15   127729664   108238488   19491176

Here are log messages of the first Young (Minor) GC at 0.102 seconds. Here is my understanding of those 3 messages:

"DefNew: 34207K->4288K(38720K)" - This message tells us that the Serial GC for the Young (New) generation, called "DefNew", reduced the Young generation heap usage from 34207K to 4288K, see "... 34207K->4288K..." in the message. The total Young generation heap size allocated was 38720K, see "...(38720K)".
"Tenured: 0K->13758K(86016K)" - This message tells us that the Tenured (Old) generation heap usage expanded from 0K to 13758K, see "...0K->13758K..." in the message. This is a result of the Young (New) GC, which promoted some live objects from the Young (New) generation to the Tenured (Old) generation heap. The total Tenured generation heap size allocated was 86016K, see "...(86016K)".
"Pause Young (Allocation Failure) 33M->17M(121M) 28.706ms" - This message tells us that the Java application was paused for a Young (Minor) GC triggered by "Allocation Failure". The heap usage was reduced from 33M to 17M, see "... 33M->17M..." in the message. The total heap size allocated was 121M, see "...(121M)...". The total time of this Young GC took 28.706ms, see "... 28.706ms".

Based those messages, we can calculate the following:

Objects removed from Young generation: 34207K - 4288K = 29919K.
Live objects moved to Tenured generation: 13758K - 0K = 13758K.
Dead objects (garbage) destroyed: 29919K - 13758K = 16161K.

Continue again with additional output in the console:

...
46   127729664   74069456   53660208
[0.591s][info][gc,heap] GC(1) DefNew: 38643K->4287K(38720K)
[0.591s][info][gc,heap] GC(1) Tenured: 13758K->44242K(86016K)
[0.591s][info][gc     ] GC(1) Pause Young (Allocation Failure)
   51M->47M(121M) 24.964ms
47   127729664   77015592   50714072
...
78   127729664   42775624   84954040
[0.617s][info][gc,heap] GC(2) DefNew: 38719K->4287K(38720K)
[0.617s][info][gc,heap] GC(2) Tenured: 44242K->73192K(86016K)
[0.617s][info][gc     ] GC(2) Pause Young (Allocation Failure)
   81M->75M(121M) 16.611ms
79   127729664   47170696   80558968

Two more Young (Minor) GC occurred. Let's continue again.

...
109   127729664   13511344   114218320
[0.653s][info][gc     ] GC(4) Pause Full (Allocation Failure)
   104M->35M(138M) 17.526ms
[0.655s][info][gc,heap] GC(3) DefNew: 38669K->0K(38784K)
[0.655s][info][gc,heap] GC(3) Tenured: 73192K->36569K(86016K)
[0.655s][info][gc     ] GC(3) Pause Young (Allocation Failure)
   109M->35M(121M) 37.570ms
110   127795200   89572168   38223032

Here are log messages of the first Full (Major) GC at 0.653 seconds. Here is my understanding of those 4 messages:

"GC(4) Pause Full (Allocation Failure) 104M->35M(138M) 17.526ms" - This message tells us that the Java application was paused for a Full (Major) GC triggered by "Allocation Failure". The heap usage was reduced from 104M to 35M, see "... 104M->35M..." in the message. The total time of this Full GC took 17.526ms, see "... 17.526ms".
"GC(3) DefNew...", "GC(3) Tenured..." and "Pause Young ..." - These message tells us that the Java application was paused for a Young GC again.
The Full GC was labeled as GC #4, and the Young GC was labeled as GC #3. So the Full GC message should have been printed after the Young GC messages.