Serial GC Tracing - Aged Live Objects

Java 8 GC Tutorials - Herong's Tutorial Examples

∟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> \progra~1\java\jdk1.8.0\bin\java -Xms480m -Xmx480m \
   -XX:NewRatio=1 -XX:SurvivorRatio=1 \
   -XX:+UseSerialGC -XX:+PrintGCDetails -XX:+PrintHeapAtGC \
   -XX:+PrintTenuringDistribution GarbageCollection2

The first GC performed as with nothing unusual. After 77 iterations, 28564824B 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   416074784   3355616
...
77   419430400   336381792   83048608
{Heap before GC invocations=0 (full 0):
 def new generation   total 163840K, used 81102K [...
  eden space 81920K,  99% used [...
  from space 81920K,   0% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   28564824 bytes,   28564824 total
: 81102K->27895K(163840K), 0.0240105 secs]
   81102K->27895K(409600K), 0.0240604 secs]

Heap after GC invocations=1 (full 0):
 def new generation   total 163840K, used 27895K [...
  eden space 81920K,   0% used [...
  from space 81920K,  34% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

The second GC performed at iteration #156. 1300952B of 28564824B "age 1" objects left from the previous GC survived and grew to "age 2".

78   419430400   389816984   29613416
...
156   419430400   307431512   111998888
{Heap before GC invocations=1 (full 0):
 def new generation   total 163840K, used 109373K [...
  eden space 81920K,  99% used [...
  from space 81920K,  34% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   31457760 bytes,   31457760 total
- age   2:    1300952 bytes,   32758712 total
: 109373K->31990K(163840K), 0.0225874 secs]
   109373K->31990K(409600K), 0.0226232 secs]

Heap after GC invocations=2 (full 0):
 def new generation   total 163840K, used 31990K [...
  eden space 81920K,   0% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

The 3rd GC happened at iteration #235. 252360B of 1300952B "age 2" objects left from the previous GC survived and grew to "age 3".

157   419430400   385623096   33807304
...
235   419430400   303227184   116203216
{Heap before GC invocations=2 (full 0):
 def new generation   total 163840K, used 113479K [...
  eden space 81920K,  99% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   31457760 bytes,   31457760 total
- age   2:    1048592 bytes,   32506352 total
- age   3:     252360 bytes,   32758712 total
: 113479K->31990K(163840K), 0.0118935 secs]
   113479K->31990K(409600K), 0.0119348 secs]

Heap after GC invocations=3 (full 0):
 def new generation   total 163840K, used 31990K [...
  eden space 81920K,   0% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

Note those 252360 B objects were not part of array element objects, (each array element object has a size of 1 MB = 11206656 B. They represents other program variables, which will not released by the test loop. They will grow older and older.

The 4th GC happened at iteration #314. 252360B "age 3" objects left from the previous GC survived and grew to "age 4" as I expected.

236   419430400   385623096   33807304
...
314   419430400   303222960   116207440
{Heap before GC invocations=3 (full 0):
 def new generation   total 163840K, used 113483K [...
  eden space 81920K,  99% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   30409168 bytes,   30409168 total
- age   2:    2097184 bytes,   32506352 total
- age   4:     252360 bytes,   32758712 total
: 113483K->31990K(163840K), 0.0091800 secs]
   113483K->31990K(409600K), 0.0092154 secs]

Heap after GC invocations=4 (full 0):
 def new generation   total 163840K, used 31990K [...
  eden space 81920K,   0% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

Finally, at GC #15, those 252360B objects reached "age 15". They will be "maturely" promoted to Tenured generation at the next Minor GC.

{Heap before GC invocations=14 (full 0):
 def new generation   total 163840K, used 113490K [...
  eden space 81920K,  99% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   31457760 bytes,   31457760 total
- age   2:    1048592 bytes,   32506352 total
- age   6:        208 bytes,   32506560 total
- age   9:         72 bytes,   32506632 total
- age  11:         56 bytes,   32506688 total
- age  15:     252360 bytes,   32759048 total
: 113490K->31991K(163840K), 0.0089940 secs]
   113490K->31991K(409600K), 0.0090286 secs]
Heap after GC invocations=15 (full 0):
 def new generation   total 163840K, used 31991K [...
  eden space 81920K,   0% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

Notice that some other long-lived objects were also created and used by the JVM. And they reached ages of 6, 9, and 11.

Here is the next GC. 246K matured objects were promoted to "tenured" generation now.

{Heap before GC invocations=15 (full 0):
 def new generation   total 163840K, used 113490K [...
  eden space 81920K,  99% used [...
  from space 81920K,  39% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 0K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

[GC (Allocation Failure) [DefNew
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age   1:   31457760 bytes,   31457760 total
- age   2:    2097184 bytes,   33554944 total
- age   7:        208 bytes,   33555152 total
- age  10:         72 bytes,   33555224 total
- age  12:         56 bytes,   33555280 total
: 113490K->32768K(163840K), 0.0093754 secs]
   113490K->33015K(409600K), 0.0094108 secs]

Heap after GC invocations=16 (full 0):
 def new generation   total 163840K, used 32768K [...
  eden space 81920K,   0% used [...
  from space 81920K,  40% used [...
  to   space 81920K,   0% used [...
 tenured generation   total 245760K, used 246K [...
   the space 245760K,   0% used [...
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}

Conclusion:

Objects grow older and older, if they were identified as live objects in "from" space in multiple rounds of GC
When objects reach the tenuring threshold age, they will be promoted to Tenured generation, even if "from" space has room to hold them.