Serial GC Tracing - Tight Heap (Part 2)

Java GC Tutorials - Herong's Tutorial Examples

∟Serial GC Tracing - Tight Heap (Part 2)

This section provides part 2 of a tutorial on tracing how Serial GC works with a tight heap size.

The third Young GC happened after another 10 iterations, because the "eden" space was 100% full again with new objects.

4   40566784   31411448   9155336
5   40566784   30275488   10291296
6   40566784   29188680   11378104
7   40566784   28052720   12514064
8   40566784   26982312   13584472
9   40566784   25895504   14671280
10   40566784   24759544   15807240
11   40566784   23689136   16877648
12   40566784   22618752   17948032
13   40566784   21482792   19083992
[debug][gc,heap] GC(2) Heap before GC invocations=2 (full 0):
                        def new generation   total 12288K, used 12287K [...
[debug][gc,heap] GC(2)   eden space 10944K, 100% used [...
[debug][gc,heap] GC(2)   from space 1344K,  99% used [...
[debug][gc,heap] GC(2)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(2)  tenured generation   total 27328K, used 7255K [...
[debug][gc,heap] GC(2)    the space 27328K,  26% used [...

[trace][gc,age ] GC(2) Age table with threshold 1 (max threshold 15)
[trace][gc,age ] GC(2) - age   1:    1376248 bytes,    1376248 total

[info ][gc,heap] GC(2) DefNew: 12287K->1343K(12288K)
[info ][gc,heap] GC(2) Tenured: 7255K->18188K(27328K)
[info ][gc     ] GC(2) Pause Young (Allocation Failure) 19M->19M(38M) 9.188ms

[debug][gc,heap] GC(2) Heap after GC invocations=3 (full 0):
                        def new generation   total 12288K, used 1343K [...
[debug][gc,heap] GC(2)   eden space 10944K,   0% used [...
[debug][gc,heap] GC(2)   from space 1344K,  99% used [...
[debug][gc,heap] GC(2)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(2)  tenured generation   total 27328K, used 18188K [...
[debug][gc,heap] GC(2)    the space 27328K,  66% used [...

Notes on the above GC:

10 iterations added 10*1024K = 10240K new objects from my application, which makes the "eden" fully used triggering this Young GC.
The GC behaved almost the same was as the previous GC.
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.
"tenured" expanded from 7255K to 18188K with 10933K, which came from two sources: 1344K promoted from the "from" and 9589K promoted directly from "eden".
So how much garbage was destroyed? We can calculate it based on what was removed from "eden": 10944K (objects from "eden") - 1344K (promoted to "from") - 9589K (promoted to "tenured" = 11K.
Since there was no dead objects resulted from the first 3 iterations of my application, 11K garbage destroyed was all from JVM. So JVM is very efficient once my application got executed with such a small amount of garbage.
At the end of GC, heap usage was 1344K in "from" + 18188K in "tenured", about 19M, which presented 13M for my application and 6M for JVM.

The fourth GC and fifth GC happened together as a combination of Young GC and Full GC after another 11 iterations, because the "eden" space was 99% full again with new objects.

14   40566784   20345600   20221184
15   40566784   19273168   21293616
16   40566784   18200736   22366048
17   40566784   17111904   23454880
18   40566784   15973920   24592864
19   40566784   14901488   25665296
20   40566784   13812656   26754128
21   40566784   12674672   27892112
22   40566784   11602240   28964544
23   40566784   10513408   30053376
24   40566784   9441000   31125784
[debug][gc,heap] GC(3) Heap before GC invocations=3 (full 0):
                        def new generation   total 12288K, used 12208K [...
[debug][gc,heap] GC(3)   eden space 10944K,  99% used [...
[debug][gc,heap] GC(3)   from space 1344K,  99% used [...
[debug][gc,heap] GC(3)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(3)  tenured generation   total 27328K, used 18188K [...
[debug][gc,heap] GC(3)    the space 27328K,  66% used [...

[info ][gc] GC(4) Pause Full (Allocation Failure) 29M->28M(38M) 24.030ms

[info ][gc,heap] GC(3) DefNew: 12208K->1840K(12288K)
[info ][gc,heap] GC(3) Tenured: 18188K->27111K(27328K)
[info ][gc] GC(3) Pause Young (Allocation Failure) 29M->28M(38M) 24.166ms

[debug][gc,heap] GC(3) Heap after GC invocations=4 (full 1):
                        def new generation   total 12288K, used 1840K [...
[debug][gc,heap] GC(3)   eden space 10944K,  16% used [...
[debug][gc,heap] GC(3)   from space 1344K,   0% used [...
[debug][gc,heap] GC(3)   to   space 1344K,   0% used [...
[debug][gc,heap] GC(3)  tenured generation   total 27328K, used 27111K [...
[debug][gc,heap] GC(3)    the space 27328K,  99% used [...

Notes on the above GC:

Young GC was triggered by 98% usage of "eden" space.
Full GC was also triggered by 99% usage of "tenured" space after the Young GC. But this Full GC could not find any dead object in "tenured". So it did not collect any garbage at all.
16% of 10944K objects left in "eden", because there was no room in "tenured" space and the objects were too big (1MB in size) to go the "from".
At the end of GC, heap usage was 16%*10944K in "eden + 0K in "from" + 27111K in "tenured", about 28M, which presented 24M for my application and 4M for JVM.