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

 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