Java GC Tutorials - Herong's Tutorial Examples - v1.12, by Herong Yang
Serial GC Tracing - Aged Live Objects
This section provides a tutorial of tracing how Serial GC increases the age of objects survived each additional GC in 'from' space.
From previous tutorials, we learned that if heap size is tight, the Serial collector skips Young generation GC and does Tenured generation GC only.
If you give a huge heap, the Serial collector does GC less frequently, and all "age 1" objects are dead by the time the next GC is triggered.
In this tutorial, let's modify our test program to keep some objects living longer.
/* GarbageCollection2.java
* Copyright (c) HerongYang.com. All Rights Reserved.
*/
class GarbageCollection2 {
public static void main(String[] a) {
java.util.Random rnd = new java.util.Random();
int max = 10000;
int min = 32;
Object[] arr = new Object[min];
Runtime rt = Runtime.getRuntime();
System.out.println("Step/TotalMemory/FreeMemory/UsedMemory:");
for (int m=0; m<max; m++) {
int k = rnd.nextInt(min);
for (int n=min-1; n>=k+1; n--) arr[n] = arr[n-1];
arr[k] = getOneMega();
long total = rt.totalMemory();
long free = rt.freeMemory();
System.out.println((m+1)+" "+total+" "+free+" "
+(total-free));
}
}
private static Object getOneMega() {
return new long[1024*128]; // 1MB
}
}
As you can see, the modification is to insert a new object at a random position of the array. If an object is inserted near the end of the array, it will have a shorter life, and get pushed out quickly.
But if an object is inserted near the beginning of the array, it will have a longer life, and get pushed out slowly.
When running GarbageCollection2.java, we need to adjust "eden" and "from" spaces to trigger GC frequently and have enough room to hold all live objects:
herong> java -Xms480m -Xmx480m -XX:+UseSerialGC \ -XX:NewRatio=1 -XX:SurvivorRatio=1 \ -Xlog:gc=info,gc+heap=debug,gc+age=trace GarbageCollection2
The first GC performed as with nothing unusual. After 55 iterations, 30223152 bytes of objects survived and labeled as "age 1". That means that some positions in array were still have no objects assigned.
Step/TotalMemory/FreeMemory/UsedMemory:
1 419430400 393215072 26215328
...
55 419430400 336591104 82839296
[debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0):
def new generation total 163840K, used 80897K ...
[debug][gc,heap] GC(0) eden space 81920K, 98% used [...
[debug][gc,heap] GC(0) from space 81920K, 0% used [...
[debug][gc,heap] GC(0) to space 81920K, 0% used [...
[debug][gc,heap] GC(0) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(0) the space 245760K, 0% used [...
[debug][gc,age ] GC(0) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(0) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(0) - age 1: 30223152 bytes, 30223152 total
[info ][gc,heap] GC(0) DefNew: 80897K->29514K(163840K)
[info ][gc,heap] GC(0) Tenured: 0K->0K(245760K)
[info ][gc ] GC(0) Pause Young (Allocation Failure)
79M->28M(400M) 25.108ms
[debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
def new generation total 163840K, used 29514K ...
[debug][gc,heap] GC(0) eden space 81920K, 0% used [...
[debug][gc,heap] GC(0) from space 81920K, 36% used [...
[debug][gc,heap] GC(0) to space 81920K, 0% used [...
[debug][gc,heap] GC(0) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(0) the space 245760K, 0% used [...
The second GC performed at iteration #156. 5043664 of 30223152 bytes of objects "age 1" left from the previous GC survived and grew to "age 2".
...
133 419430400 305983072 113447328
[debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0):
def new generation total 163840K, used 110788K ...
[debug][gc,heap] GC(1) eden space 81920K, 99% used [...
[debug][gc,heap] GC(1) from space 81920K, 36% used [...
[debug][gc,heap] GC(1) to space 81920K, 0% used [...
[debug][gc,heap] GC(1) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(1) the space 245760K, 0% used [...
[debug][gc,age ] GC(1) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(1) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(1) - age 1: 30409304 bytes, 30409304 total
[trace][gc,age ] GC(1) - age 2: 5043664 bytes, 35452968 total
[info ][gc,heap] GC(1) DefNew: 110788K->34622K(163840K)
[info ][gc,heap] GC(1) Tenured: 0K->0K(245760K)
[info ][gc ] GC(1) Pause Young (Allocation Failure)
108M->33M(400M) 145373.981ms
[debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0):
def new generation total 163840K, used 34622K ...
[debug][gc,heap] GC(1) eden space 81920K, 0% used [...
[debug][gc,heap] GC(1) from space 81920K, 42% used [...
[debug][gc,heap] GC(1) to space 81920K, 0% used [...
[debug][gc,heap] GC(1) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(1) the space 245760K, 0% used [...
The 3rd GC happened at iteration #212. 2946480 of 5043664 bytes of objects "age 2" left from the previous GC survived and grew to "age 3".
...
212 419430400 300538024 118892376
[debug][gc,heap] GC(2) Heap before GC invocations=2 (full 0):
def new generation total 163840K, used 116105K ...
[debug][gc,heap] GC(2) eden space 81920K, 99% used [...
[debug][gc,heap] GC(2) from space 81920K, 42% used [...
[debug][gc,heap] GC(2) to space 81920K, 0% used [...
[debug][gc,heap] GC(2) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(2) the space 245760K, 0% used [...
[debug][gc,age ] GC(2) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(2) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(2) - age 1: 28311984 bytes, 28311984 total
[trace][gc,age ] GC(2) - age 2: 4194504 bytes, 32506488 total
[trace][gc,age ] GC(2) - age 3: 2946480 bytes, 35452968 total
[info ][gc,heap] GC(2) DefNew: 116105K->34622K(163840K)
[info ][gc,heap] GC(2) Tenured: 0K->0K(245760K)
[info ][gc ] GC(2) Pause Young (Allocation Failure)
113M->33M(400M) 11.695ms
[debug][gc,heap] GC(2) Heap after GC invocations=3 (full 0):
def new generation total 163840K, used 34622K ...
[debug][gc,heap] GC(2) eden space 81920K, 0% used [...
[debug][gc,heap] GC(2) from space 81920K, 42% used [...
[debug][gc,heap] GC(2) to space 81920K, 0% used [...
[debug][gc,heap] GC(2) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(2) the space 245760K, 0% used [...
The 4th GC happened at iteration #291. 2946480 bytes of objects "age 3" left from the previous GC survived and grew to "age 4". It's interesting to see 136 bytes of objects "age 3" resulted from this GC. They are clearly JVM objects, by my objects are 1MB in size.
...
291 419430400 300532168 118898232
[debug][gc,heap] GC(3) Heap before GC invocations=3 (full 0):
def new generation total 163840K, ...
[debug][gc,heap] GC(3) eden space 81920K, 99% used [...
[debug][gc,heap] GC(3) from space 81920K, 42% used [...
[debug][gc,heap] GC(3) to space 81920K, 0% used [...
[debug][gc,heap] GC(3) tenured generation total 245760K, ...
[debug][gc,heap] GC(3) the space 245760K, 0% used [...
[debug][gc,age ] GC(3) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(3) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(3) - age 1: 30409168 bytes, 30409168 total
[trace][gc,age ] GC(3) - age 2: 2097184 bytes, 32506352 total
[trace][gc,age ] GC(3) - age 3: 136 bytes, 32506488 total
[trace][gc,age ] GC(3) - age 4: 2946480 bytes, 35452968 total
[info ][gc,heap] GC(3) DefNew: 116111K->34622K(163840K)
[info ][gc,heap] GC(3) Tenured: 0K->0K(245760K)
[info ][gc ] GC(3) Pause Young (Allocation Failure)
113M->33M(400M) 10.275ms
[debug][gc,heap] GC(3) Heap after GC invocations=4 (full 0):
def new generation total 163840K, used 34622K ...
[debug][gc,heap] GC(3) eden space 81920K, 0% used [...
[debug][gc,heap] GC(3) from space 81920K, 42% used [...
[debug][gc,heap] GC(3) to space 81920K, 0% used [...
[debug][gc,heap] GC(3) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(3) the space 245760K, 0% used [...
Finally, at GC #15, 2460432 bytes of objects reached "age 15". They will be "maturely" promoted to Tenured generation at the next Minor GC. Some other long-lived, age 5, 7, 8, 9, and 14, objects were also created and used by the JVM.
...
1159 419430400 301007184 118423216
[debug][gc,heap] GC(14) Heap before GC invocations=14 (full 0):
def new generation total 163840K, used 115647K ...
[debug][gc,heap] GC(14) eden space 81920K, 99% used [...
[debug][gc,heap] GC(14) from space 81920K, 41% used [...
[debug][gc,heap] GC(14) to space 81920K, 0% used [...
[debug][gc,heap] GC(14) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(14) the space 245760K, 0% used [...
[debug][gc,age ] GC(14) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(14) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(14) - age 1: 30409168 bytes, 30409168 total
[trace][gc,age ] GC(14) - age 2: 1048592 bytes, 31457760 total
[trace][gc,age ] GC(14) - age 3: 1048592 bytes, 32506352 total
[trace][gc,age ] GC(14) - age 5: 680 bytes, 32507032 total
[trace][gc,age ] GC(14) - age 7: 136 bytes, 32507168 total
[trace][gc,age ] GC(14) - age 8: 56 bytes, 32507224 total
[trace][gc,age ] GC(14) - age 9: 136 bytes, 32507360 total
[trace][gc,age ] GC(14) - age 14: 136 bytes, 32507496 total
[trace][gc,age ] GC(14) - age 15: 2460432 bytes, 34967928 total
[info ][gc,heap] GC(14) DefNew: 115647K->34148K(163840K)
[info ][gc,heap] GC(14) Tenured: 0K->0K(245760K)
[info ][gc ] GC(14) Pause Young (Allocation Failure)
112M->33M(400M) 9.444ms
[debug][gc,heap] GC(14) Heap after GC invocations=15 (full 0):
def new generation total 163840K, used 34148K ...
[debug][gc,heap] GC(14) eden space 81920K, 0% used [...
[debug][gc,heap] GC(14) from space 81920K, 41% used [...
[debug][gc,heap] GC(14) to space 81920K, 0% used [...
[debug][gc,heap] GC(14) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(14) the space 245760K, 0% used [...
Here is the next GC. 2402K matured objects were promoted to "tenured" generation now.
...
1238 419430400 301006992 118423408
[debug][gc,heap] GC(15) Heap before GC invocations=15 (full 0):
def new generation total 163840K, ...
[debug][gc,heap] GC(15) eden space 81920K, 99% used [...
[debug][gc,heap] GC(15) from space 81920K, 41% used [...
[debug][gc,heap] GC(15) to space 81920K, 0% used [...
[debug][gc,heap] GC(15) tenured generation total 245760K, used 0K ...
[debug][gc,heap] GC(15) the space 245760K, 0% used [...
[debug][gc,age ] GC(15) Desired survivor size 41943040 bytes,
new threshold 15 (max threshold 15)
[trace][gc,age ] GC(15) Age table with threshold 15 (max threshold 15)
[trace][gc,age ] GC(15) - age 1: 28311984 bytes, 28311984 total
[trace][gc,age ] GC(15) - age 2: 4194368 bytes, 32506352 total
[trace][gc,age ] GC(15) - age 6: 680 bytes, 32507032 total
[trace][gc,age ] GC(15) - age 8: 136 bytes, 32507168 total
[trace][gc,age ] GC(15) - age 9: 56 bytes, 32507224 total
[trace][gc,age ] GC(15) - age 10: 136 bytes, 32507360 total
[trace][gc,age ] GC(15) - age 15: 136 bytes, 32507496 total
[info ][gc,heap] GC(15) DefNew: 115647K->31745K(163840K)
[info ][gc,heap] GC(15) Tenured: 0K->2402K(245760K)
[info ][gc ] GC(15) Pause Young (Allocation Failure)
112M->33M(400M) 245241.142ms
[debug][gc,heap] GC(15) Heap after GC invocations=16 (full 0):
def new generation total 163840K, used 31745K ...
[debug][gc,heap] GC(15) eden space 81920K, 0% used [...
[debug][gc,heap] GC(15) from space 81920K, 38% used [...
[debug][gc,heap] GC(15) to space 81920K, 0% used [...
[debug][gc,heap] GC(15) tenured generation total 245760K, used 2402K ...
[debug][gc,heap] GC(15) the space 245760K, 0% used [...
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 - 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