Java 8 GC Tutorials - Herong's Tutorial Examples - v1.03, by Dr. Herong Yang
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 with a size of 1200 MB and watch how the Serial GC does garbage collections.
"-XX:+PrintHeapAtGC" and "-XX:+PrintTenuringDistribution" options are used print GC tracing information:
herong> \progra~1\java\jdk1.8.0\bin\java -Xms1200m -Xmx1200m \ -XX:+UseSerialGC -XX:+PrintGCDetails -XX:+PrintHeapAtGC \ -XX:+PrintTenuringDistribution GarbageCollection
The first GC happened after 306 iterations, because the "eden" space was full with 327426K new objects:
Step/TotalMemory/FreeMemory/UsedMemory: 1 1216348160 1202926208 13421952 ... 306 1216348160 881325864 335022296 {Heap before GC invocations=0 (full 0): def new generation total 368640K, used 327426K [0x04800000, ... eden space 327680K, 99% used [... from space 40960K, 0% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 0K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d800000, ... [GC (Allocation Failure) [DefNew... Desired survivor size 20971520 bytes, new threshold 1 (max 15) - age 1: 33531432 bytes, 33531432 total ...: 327426K->32745K(368640K), 0.0293776 secs] 327426K->32745K(1187840K), 0.0294134 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] Heap after GC invocations=1 (full 0): def new generation total 368640K, used 32745K [0x04800000, ... eden space 327680K, 0% used [... from space 40960K, 79% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 0K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d800000, ... }
This was a simple Young generation GC, which removed all dead objects and left 32745K live objects in "from" space. The size of live objects matches my expectation, the test application only uses 32MB in the array.
The second GC happened at 613rd iteration, because the "eden" space was full again with new objects.
307 1216348160 1175994264 40353896 ... 613 1216348160 847272408 369075752 {Heap before GC invocations=1 (full 0): def new generation total 368640K, used 360425K [0x04800000, ... eden space 327680K, 100% used [... from space 40960K, 79% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 0K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d800000, ... [GC (Allocation Failure) [DefNew... Desired survivor size 20971520 bytes, new threshold 1 (max 15) - age 1: 33543536 bytes, 33543536 total ...: 360425K->32757K(368640K), 0.0308081 secs] 360425K->33001K(1187840K), 0.0308329 secs] [Times: user=0.00 sys=0.03, real=0.03 secs] Heap after GC invocations=2 (full 0): def new generation total 368640K, used 32757K [0x04800000, ... eden space 327680K, 0% used [... from space 40960K, 79% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 243K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d83cfa8, ... }
This was also a simple Young generation GC, which removed all dead objects and left 32757K live objects in "from" space as I expected.
Also note that, "age 1" objects left from the first GC were all dead objects, so no objects were labeled as "age 2".
The 3rd GC happened at 923rd iteration, because the "eden" space was full again with new objects.
614 1216348160 1175679688 40668472 ... 923 1216348160 847010536 369337624 {Heap before GC invocations=2 (full 0): def new generation total 368640K, used 360437K [0x04800000, ... eden space 327680K, 100% used [... from space 40960K, 79% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 243K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d83cfa8, ... [GC (Allocation Failure) [DefNew... Desired survivor size 20971520 bytes, new threshold 1 (max 15) - age 1: 33871264 bytes, 33871264 total ...: 360437K->33077K(368640K), 0.0113341 secs] 360681K->33321K(1187840K), 0.0113593 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] Heap after GC invocations=3 (full 0): def new generation total 368640K, used 33077K [0x04800000, ... eden space 327680K, 0% used [... from space 40960K, 80% used [... to space 40960K, 0% used [... tenured generation total 819200K, used 244K [0x1d800000, ... the space 819200K, 0% used [0x1d800000, 0x1d83d068, ... }
This was also a simple Young generation GC, which removed all dead objects and left 33077K live objects in "from" space as I expected.
Also note that, "age 1" objects left from the second GC were all dead objects, so no objects were labeled as "age 2".
All subsequent GCs were behaved similar the 3rd GC.
Conclusion:
Table of Contents
Heap Memory Area and Size Control
JVM Garbage Collection Logging
Introduction of Garbage Collectors
►Serial Collector - "+XX:+UseSerialGC"
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 - 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" not 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"
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