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

 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 - 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

 Garbage Collection Performance Test Summary

 Archived Tutorials

 References

 Full Version in PDF/EPUB