Serial GC Tracing - Tight Heap

Java GC Tutorials - Herong's Tutorial Examples

∟Serial GC Tracing - Tight Heap

This section provides a tutorial on tracing how Serial GC works with a tight heap size.

We know that our test program GarbageCollection.java works on an array of 32 MB data. Let's run with a tight heap size of 40 MB and watch how the Serial GC does garbage collections.

"gc=info", "gc+heap=debug" and "-Xlog:gc+age=trace" options are used to print GC tracing information:

herong> java -Xms40m -Xmx40m -XX:+UseSerialGC \
   -Xlog:gc=info,gc+heap=debug,gc+age=trace GarbageCollection

The first Young GC happened during the JVM startup process, because the "eden" space was full with 10944K new objects:

[debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0):
                        def new generation   total 12288K, used 10944K [...
[debug][gc,heap] GC(0)   eden space 10944K, 100% used [...
[debug][gc,heap] GC(0)   from space 1344K,   0% used [...
[debug][gc,heap] GC(0)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(0)  tenured generation   total 27328K, used 0K [...
[debug][gc,heap] GC(0)    the space 27328K,   0% used [...

[debug][gc,age] GC(0) Desired survivor size 688128 bytes,
                       new threshold 1 (max threshold 15)
[trace][gc,age] GC(0) Age table with threshold 1 (max threshold 15)
[trace][gc,age] GC(0) - age   1:    1376256 bytes,    1376256 total

[info][gc,heap] GC(0) DefNew: 10944K->1344K(12288K)
[info][gc,heap] GC(0) Tenured: 0K->2024K(27328K)
[info][gc] GC(0) Pause Young (Allocation Failure) 10M->3M(38M) 7.485ms

[debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
                        def new generation   total 12288K, used 1344K [...
[debug][gc,heap] GC(0)   eden space 10944K,   0% used [...
[debug][gc,heap] GC(0)   from space 1344K, 100% used [...
[debug][gc,heap] GC(0)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(0)  tenured generation   total 27328K, used 2024K [...
[debug][gc,heap] GC(0)    the space 27328K,   7% used [...

Notes on the above GC:

The primary trigger for Young generation GC is that when "eden" is fully allocated with new objects.
Out of 10944K objects in the "eden", 1344K was promoted to "from". The remaining 10944K - 1344K = 9600K was destroyed as garbage or promoted to "tenured".
All 1344K objects promoted to "from" was marked as "age 1" objects.
"tenured" was expanded from 0K to 2024K, which was promoted directly from "eden". So there was 9600K - 2024K = 7576K garbage being collected.
At the end of GC, heap usage was 1344K in "from" + 2024K in "tenured", about 3M.
So JVM needed more than 10944K "eden" space to start. And 7576K (70%) was occupied with dead objects.

The second Young GC happened after another 3 iterations, because the "eden" space was 99% full again with new objects.

Step/TotalMemory/FreeMemory/UsedMemory:
1   40566784   29467528   11099256
2   40566784   27789568   12777216
3   40566784   26699544   13867240
[debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0):
                        def new generation   total 12288K, used 12285K [...
[debug][gc,heap] GC(1)   eden space 10944K,  99% used [...
[debug][gc,heap] GC(1)   from space 1344K, 100% used [...
[debug][gc,heap] GC(1)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(1)  tenured generation   total 27328K, used 2025K [...
[debug][gc,heap] GC(1)    the space 27328K,   7% used [...

[trace][gc,age ] GC(1) Age table with threshold 1 (max threshold 15)
[trace][gc,age ] GC(1) - age   1:    1376248 bytes,    1376248 total

[info ][gc,heap] GC(1) DefNew: 12285K->1343K(12288K)
[info ][gc,heap] GC(1) Tenured: 2025K->7255K(27328K)
[info ][gc     ] GC(1) Pause Young (Allocation Failure) 13M->8M(38M) 9.055ms

[debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0):
                        def new generation   total 12288K, used 1343K [...
[debug][gc,heap] GC(1)   eden space 10944K,   0% used [...
[debug][gc,heap] GC(1)   from space 1344K,  99% used [...
[debug][gc,heap] GC(1)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(1)  tenured generation   total 27328K, used 7255K [...
[debug][gc,heap] GC(1)    the space 27328K,  26% used [...

Notes on the above GC:

The primary trigger for Young generation GC is that when "eden" is fully allocated with new objects.
Out of 10944K objects in the "eden", 3072K was 3 1MB objects created from my application. The remaining 10944K - 3072K = 7872K was new objects created by the JVM system.
Out of 10944K objects in the "eden", 1344K was promoted to "from" as "age 1" objects. The remaining 10944K - 1344K = 9600K was destroyed as garbage or promoted to "tenured".
The original 1344K "age 1" objects was promoted to "tenured". If they stayed in "from", they would be labeled as "age 2".
"tenured" expanded from 2025K to 7255K with 5230K, which came from two sources: 1344K promoted from the "from" and 3886K promoted directly from "eden".
So how much garbage was destroyed? We can calculate it based on what was removed from "eden": 10944K (objects from "eden") - 1344K (promoted to "from") - 3886K (promoted to "tenured" = 5714K.
Since there was no dead objects resulted from the first 3 iterations of my application, 5714K garbage destroyed was all from JVM.
At the end of GC, heap usage was 1344K in "from" + 7255K in "tenured", about 8M, which presented 3M for my application and 5M for JVM.