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:

C:\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:

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:

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:

Table of Contents

 About This Book

 Heap Memory Area and Size Control

 JVM Garbage Collection Logging

 Introduction of Garbage Collectors

Serial Collector - "+XX:+UseSerialGC"

 What Is Serial Collector

 GC Log Message Format for Serial Collector

 GC Log Message Examples of Serial Collector

 Log Message Types from Serial Collector

 Serial Collector Stops Application for Minor/Major GC

 Usage Report on Heap Memory Areas

 Default NewRatio - Old vs. New Generation

 "-XX:NewRatio" - Ratio of Tenured and "new" Generation

 "-XX:SurvivorRatio" - Ratio of Eden and Survivor Space

 Serial GC Tracing - Tight Heap

 Serial GC Tracing - Tight Heap (Part 2)

 Serial GC Tracing - Tight Heap (Part 3)

Serial GC Tracing - Plenty of Heap

 Serial GC Tracing - Aged Live Objects

 Serial GC Tracing - Tenuring Threshold

 "-XX:TargetSurvivorRatio" - Second Tenuring Condition

 Serial GC Tracing - Tenuring Threshold Controlled

 "-XX:+NeverTenure" and "-XX:+AlwaysTenure" Working

 Minor GC Triggering Condition of Serial Collector

 Parallel Collector - "+XX:+UseParallelGC"

 Concurrent Mark-Sweep (CMS) Collector - "+XX:+UseConcMarkSweepGC"

 Garbage First (G1) Collector - "+XX:+UseG1GC"

 The Z Garbage Collector (ZGC) - "+XX:+UseZGC"

 Object References and Garbage Collection

 Garbage Collection Performance Test Program

 Performance Tests on Serial Collector

 Performance Tests on Parallel collector

 Performance Tests on Concurrent collector

 Performance Tests on G1 collector

 Garbage Collection Performance Test Summary

 References

 Full Version in PDF/EPUB