Serial GC Tracing - Plenty of Heap

Java GC Tutorials - Herong's Tutorial Examples

∟Serial GC Tracing - Plenty of Heap

This section provides a tutorial of tracing how Serial GC works with a huge heap size, plenty of memory in 'new' generation.

We know that our test program GarbageCollection.java uses Tenured generation collector only if we gave 40 MB of heap, Let's run it again with a size of 1200 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 -Xms1200m -Xmx1200m -XX:+UseSerialGC \
   -Xlog:gc=info,gc+heap=debug,gc+age=trace GarbageCollection

The first GC happened after 276 iterations, because the "eden" space was full with 327426K new objects:

Step/TotalMemory/FreeMemory/UsedMemory:
1   1216348160   1202926208   13421952
...
276   1216348160   880803840   335544320
[5.687s][debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0):
                                def new generation   total 368640K, ...
[5.687s][debug][gc,heap] GC(0)   eden space 327680K, 100% used [...
[5.687s][debug][gc,heap] GC(0)   from space 40960K,   0% used [...
[5.687s][debug][gc,heap] GC(0)   to   space 40960K,   0% used [...
[5.687s][debug][gc,heap] GC(0)  tenured generation   total 819200K, ...
[5.687s][debug][gc,heap] GC(0)    the space 819200K,   0% used [...

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

[5.718s][info ][gc,heap] GC(0) DefNew: 327680K->35738K(368640K)
[5.718s][info ][gc,heap] GC(0) Tenured: 0K->0K(819200K)
[5.718s][info ][gc     ] GC(0) Pause Young (Allocation Failure)
                               320M->34M(1160M) 31.307ms

[5.718s][debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
                                def new generation   total 368640K, ...
[5.718s][debug][gc,heap] GC(0)   eden space 327680K,   0% used [...
[6.330s][debug][gc,heap] GC(0)   from space 40960K,  87% used [...
[6.330s][debug][gc,heap] GC(0)   to   space 40960K,   0% used [...
[6.330s][debug][gc,heap] GC(0)  tenured generation   total 819200K, ...
[6.330s][debug][gc,heap] GC(0)    the space 819200K,   0% used [...

Notes on the above GC:

This was a simple Young generation GC, which removed all dead objects and left 87% of 40960K (about 35635K) live objects in "from" space.
My application kept 32 1MB live objects. Other live objects were used by JVM.
The "tenured" generation was not used all.

The second GC happened at 576th iteration, because the "eden" space was full again with new objects.

277   1216348160   1172665408   43682752
...
576   1216348160   844269464   372078696
[debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0):
                        def new generation   total 368640K, used 363358K ...
[debug][gc,heap] GC(1)   eden space 327680K,  99% used [...
[debug][gc,heap] GC(1)   from space 40960K,  87% used [...
[debug][gc,heap] GC(1)   to   space 40960K,   0% used [...
[debug][gc,heap] GC(1)  tenured generation   total 819200K, used 0K [...
[debug][gc,heap] GC(1)    the space 819200K,   0% used [...

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

[info ][gc,heap] GC(1) DefNew: 363358K->34069K(368640K)
[info ][gc,heap] GC(1) Tenured: 0K->2488K(819200K)
[info ][gc     ] GC(1) Pause Young (Allocation Failure)
                       354M->35M(1160M) 28.914ms

[debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0):
                        def new generation   total 368640K, used 34069K ...
[debug][gc,heap] GC(1)   eden space 327680K,   0% used [...
[debug][gc,heap] GC(1)   from space 40960K,  83% used [...
[debug][gc,heap] GC(1)   to   space 40960K,   0% used [...
[debug][gc,heap] GC(1)  tenured generation   total 819200K, used 2488K ...
[debug][gc,heap] GC(1)    the space 819200K,   0% used [...

Notes on the above GC:

This was a simple Young generation GC, which removed all dead objects and left 83% of 40960K (about 33997K) live objects in "from" space.
My application kept 32 1MB live objects. Other live objects were used by JVM.
"age 1" objects left from the first GC were all dead objects, so no objects were labeled as "age 2".
2488K live objects were promoted to "tenured" generation. This should not happen, be cause "from" still has enough free space.

The 3rd GC happened at 880th iteration, because the "eden" space was full again with new objects.

577   1216348160   1172253392   44094768
...
880   1216348160   843369040   372979120
[debug][gc,heap] GC(2) Heap before GC invocations=2 (full 0):
                        def new generation   total 368640K, used 361749K ...
[debug][gc,heap] GC(2)   eden space 327680K, 100% used [...
[debug][gc,heap] GC(2)   from space 40960K,  83% used [...
[debug][gc,heap] GC(2)   to   space 40960K,   0% used [...
[debug][gc,heap] GC(2)  tenured generation   total 819200K, used 2488K ...
[debug][gc,heap] GC(2)    the space 819200K,   0% used [...

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

[info ][gc,heap] GC(2) DefNew: 361749K->33237K(368640K)
[info ][gc,heap] GC(2) Tenured: 2488K->2488K(819200K)
[info ][gc     ] GC(2) Pause Young (Allocation Failure)
                       355M->34M(1160M) 16.540ms

[debug][gc,heap] GC(2) Heap after GC invocations=3 (full 0):
                        def new generation   total 368640K, used 33237K ...
[debug][gc,heap] GC(2)   eden space 327680K,   0% used [...
[debug][gc,heap] GC(2)   from space 40960K,  81% used [...
[debug][gc,heap] GC(2)   to   space 40960K,   0% used [...
[debug][gc,heap] GC(2)  tenured generation   total 819200K, used 2488K ...
[debug][gc,heap] GC(2)    the space 819200K,   0% used [...

The above GC behaved almost the same way as the second GC.

All subsequent GCs behaved also similarly.

Conclusion:

If "from" space is big enough to hold all live objects, no objects are moved the "tenured" generation.
No objects will grow older than age 1 in "from" space, if they are released by the application before the next GC.
If heap size is huge with enough space in "new" generation, most GC mark-sweep processes will be happening in "young" generation. The application is basically using Young generation garbage collector only.