Java 8 GC Tutorials - Herong's Tutorial Examples - v1.03, by Dr. Herong Yang
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.
"-XX:+PrintHeapAtGC" and "-XX:+PrintTenuringDistribution" options are used print GC tracing information:
herong> \progra~1\java\jdk1.8.0\bin\java -Xms40m -Xmx40m \ -XX:+UseSerialGC -XX:+PrintGCDetails -XX:+PrintHeapAtGC \ -XX:+PrintTenuringDistribution GarbageCollection
The first GC happened after 9 iterations, because the "eden" space was full with 10944K new objects:
Step/TotalMemory/FreeMemory/UsedMemory: 1 40566784 38701808 1864976 2 40566784 37849776 2717008 3 40566784 36691656 3875128 4 40566784 35615488 4951296 5 40566784 34539320 6027464 6 40566784 33463152 7103632 7 40566784 32452536 8114248 8 40566784 31359968 9206816 9 40566784 30283800 10282984 {Heap before GC invocations=0 (full 0): def new generation total 12288K, used 10944K [0x04800000, ... eden space 10944K, 100% used [... from space 1344K, 0% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 0K [0x05550000, ... the space 27328K, 0% used [0x05550000, 0x05550000, ... [GC (Allocation Failure) [DefNew... Desired survivor size 688128 bytes, new threshold 1 (max 15) - age 1: 1376256 bytes, 1376256 total ...: 10944K->1344K(12288K), 0.0265366 secs] 10944K->10582K(39616K), 0.0266889 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] Heap after GC invocations=1 (full 0): def new generation total 12288K, used 1344K [0x04800000, ... eden space 10944K, 0% used [... from space 1344K, 100% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 9238K [0x05550000, ... the space 27328K, 33% used [0x05550000, 0x05e55808, ... }
Notes on the above GC:
The second GC happened after another 11 iterations, because the "eden" space was 99% full again with new objects.
10 40566784 29665256 10901528 11 40566784 28589776 11977008 12 40566784 27432408 13134376 13 40566784 26356992 14209792 14 40566784 25281576 15285208 15 40566784 24206160 16360624 16 40566784 23130744 17436040 17 40566784 22104480 18462304 18 40566784 21029064 19537720 19 40566784 19953648 20613136 20 40566784 18878232 21688552 {Heap before GC invocations=1 (full 0): def new generation total 12288K, used 12198K [0x04800000, ... eden space 10944K, 99% used [... from space 1344K, 100% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 9238K [0x05550000, ... the space 27328K, 33% used [0x05550000, 0x05e55808, ... [GC (Allocation Failure) [DefNew... Desired survivor size 688128 bytes, new threshold 1 (max 15) - age 1: 1376248 bytes, 1376248 total ...: 12198K->1343K(12288K), 0.0262081 secs] 21436K->21303K(39616K), 0.0263147 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] Heap after GC invocations=2 (full 0): def new generation total 12288K, used 1343K [0x04800000, ... eden space 10944K, 0% used [... from space 1344K, 99% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 19959K [0x05550000, ... the space 27328K, 73% used [0x05550000, 0x068cdeb8, ... }
Notes on the above GC:
The third GC happened after another 10 iterations, because the "eden" space was 99% full again with new objects.
21 40566784 17939648 22627136 22 40566784 16783360 23783424 23 40566784 15709024 24857760 24 40566784 14634688 25932096 25 40566784 13560352 27006432 26 40566784 12486016 28080768 27 40566784 11477232 29089552 28 40566784 10386496 30180288 29 40566784 9312160 31254624 30 40566784 8237824 32328960 {Heap before GC invocations=2 (full 0): def new generation total 12288K, used 12123K [...) eden space 10944K, 98% used [... from space 1344K, 99% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 19959K [... the space 27328K, 73% used [... [GC (Allocation Failure) [DefNew: 12123K->12123K(12288K), 0.0001075 secs] [Tenured: 19959K->27313K(27328K), 0.0308239 secs] 32083K->31961K(39616K), [Metaspace: 1556K->1556K(4480K)], 0.0310867 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] Heap after GC invocations=3 (full 1): def new generation total 12288K, used 4648K [...) eden space 10944K, 42% used [... from space 1344K, 0% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 27313K [... the space 27328K, 99% used [... }
Notes on the above GC:
The 4th GC happened after another 7 iterations, because the "eden" space was 99% full again with new objects.
31 40566784 7288664 33278120 32 40566784 6132672 34434112 33 40566784 5058632 35508152 34 40566784 3984592 36582192 35 40566784 2910552 37656232 36 40566784 1836512 38730272 37 40566784 866960 39699824 {Heap before GC invocations=3 (full 1): def new generation total 12288K, used 12224K [0x04800000, ... eden space 10944K, 100% used [... from space 1344K, 95% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 27313K [0x05550000, ... the space 27328K, 99% used [0x05550000, 0x06ffc550, ... [Full GC (Allocation Failure) [Tenured: 27313K->27278K(27328K), 0.0232771 secs] 39537K->33247K(39616K), [Metaspace: 1556K->1556K(4480K)], 0.0233722 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] Heap after GC invocations=4 (full 2): def new generation total 12288K, used 5968K [0x04800000, ... eden space 10944K, 54% used [... from space 1344K, 0% used [... to space 1344K, 0% used [... tenured generation total 27328K, used 27278K [0x05550000, ... the space 27328K, 99% used [0x05550000, 0x06ff38d8, ... }
Notes on the above GC:
All subsequent GCs were behaved similar the 4th 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