Serial GC Tracing - Tight Heap

Java 8 GC Tutorials - Herong's Tutorial Examples

∟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 primary trigger for Young generation GC is that when "eden" is fully allocated with new objects.
The Serial collector marked 10582K objects as live objects, which is pretty accurate because we have 9*1024K (might be 10*1024, if this GC happened right after the 10th element was added and before the "println()" statement was executed) objects loaded in the array and some other local variables.
Since "from" space's capacity is 1344K, so 1344K of 10582K live objects were promoted to "from" space and labeled as "age 1" objects.
"age 1" objects are objects survived 1 round of GC.
The remaining 9238K of 10582K live objects had to be promoted from "eden" space to "tenured" generation directly.
In summary, this GC was a Young generation GC and it did not find any large dead objects (because the program did not released any yet). The heap was holding 10MB objects in "from" space and "tenured" generation at the end.

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:

11 iterations added 11*1024K (or maybe 10*1024K, because the 10th elements were allocated before the first GC) in the "eden" space.
All 1344K objects in "from" space before this GC are still referenced by the array. So they were live objects and promoted to "tenured" generation.
After empty the "from" space, 1376248 bytes in "eden" space were promoted to "from" space and labeled as "age 1" objects.
The remaining live objects had to be promoted from "from" space to "tenured" generation directly.
In summary, this GC was a Young generation GC and it did not find any large dead objects (because the program did not released any yet). The heap was holding 20MB objects in "from" space and "tenured" generation at the end.

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:

I think was triggered by 98% usage of "eden" space. But "tenured" generation was 73% full too. So Tenured (full) GC was actually triggered.
Since all 30MB objects were live objects referenced by the array, the Serial collector decided to fill "tenured" generation with 26MB and left 4MB in "eden" space.
The Serial collector gave up using "from" survivor space, because it is too small to hold remaining 4MB live objects.
In summary, this GC was a Tenured generation GC and it did not find any large dead objects (because the program did not released any yet). The heap was holding 30MB objects in "eden" space and "tenured" generation at the end.

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:

At iteration #37, 7MB new objects were allocated and 5MB objects were released from the array.
The Serial collector did a Tenured generation GC and removed 5MB dead objects from "tenured" generation.
Remaining 32MB objects were live objects referenced by the array, the Serial collector decided to fill "tenured" generation with 27MB and left 5MB in "eden" space.
In summary, this GC was a Tenured generation GC and it did find 5MB dead objects and removed them. The heap was holding 32MB objects in "eden" space and "tenured" generation at the end.
This GC was also labeled as "Full GC" in the log message, because it performed GC in both Young and Tenured generations.

All subsequent GCs were behaved similar the 4th GC.

Conclusion:

GCs are triggered when "eden" space is full.
If the collector is doing mark-sweep process on "new" generation only, is it considered as simple Young generation GC, also called minor GC.
If the collector is doing mark-sweep process on "tenured" generation only, is it considered as simple Tenured generation GC, also called major GC.
If the collector is doing mark-sweep process on both "new" and "tenured" generations, is it considered as "mixed" GC, or "full" GC.
If "tenured" generation is full when GC is triggered, it will be labeled as "Full GC" in the log message.
If heap size is tight, just enough to hold all live objects, most GC mark-sweep processes will be happening in "tenured" generation. The application is basically using Tenured generation garbage collector only.