GC Log Message Examples of Serial Collector

Java GC Tutorials - Herong's Tutorial Examples

∟GC Log Message Examples of Serial Collector

This section provides an example of GC log messages generated from the Serial Collector.

If you run the program again with a given heap size range, you will get more GC log message examples. Below is a list of some GC log messages with my comments:

herong> java -Xms2m -Xmx64m -XX:+UseSerialGC -Xlog:gc,gc+heap=info \
   GarbageCollection

[0.009s][info][gc] Using Serial
[0.055s][info][gc,heap] GC(0) DefNew: 1024K->128K(1152K)
[0.055s][info][gc,heap] GC(0) Tenured: 0K->418K(768K)
[0.055s][info][gc     ] GC(0) Pause Young (Allocation Failure)
   1M->0M(1M) 1.188ms

   -- A Young GC occurred in JVM start-up process
      Some small objects used by the JVM were deallocated.

[0.113s][info][gc     ] GC(2) Pause Full (Allocation Failure)
   0M->0M(2M) 2.154ms
[0.113s][info][gc,heap] GC(1) DefNew: 1152K->0K(1152K)
[0.113s][info][gc,heap] GC(1) Tenured: 418K->913K(1524K)
[0.113s][info][gc     ] GC(1) Pause Young (Allocation Failure)
   1M->0M(2M) 3.419ms

   -- A Young GC followed by a Full GC occurred in JVM start-up process
      More objects needed by the JVM
    Heap size increased from 1M to 2M
    This Full GC is unnecessary, JVM should be started with a larger heap

[0.151s][info][gc,heap] GC(3) DefNew: 1023K->127K(1152K)
[0.151s][info][gc,heap] GC(3) Tenured: 913K->1205K(1524K)
[0.151s][info][gc     ] GC(3) Pause Young (Allocation Failure)
   1M->1M(2M) 0.824ms
[0.214s][info][gc,heap] GC(4) DefNew: 1151K->128K(1152K)
[0.214s][info][gc,heap] GC(4) Tenured: 1205K->1447K(1524K)
[0.214s][info][gc     ] GC(4) Pause Young (Allocation Failure)
   2M->1M(2M) 1.110ms
[0.257s][info][gc     ] GC(6) Pause Full (Allocation Failure)
   1M->1M(2M) 3.436ms
[0.257s][info][gc,heap] GC(5) DefNew: 1152K->31K(1472K)
[0.257s][info][gc,heap] GC(5) Tenured: 1447K->1908K(3180K)
[0.257s][info][gc     ] GC(5) Pause Young (Allocation Failure)
   2M->1M(4M) 4.325ms
[0.315s][info][gc,heap] GC(7) DefNew: 1344K->127K(1472K)
[0.315s][info][gc,heap] GC(7) Tenured: 1908K->2154K(3180K)
[0.315s][info][gc     ] GC(7) Pause Young (Allocation Failure)
   3M->2M(4M) 1.872ms
[0.345s][info][gc,heap] GC(8) DefNew: 1471K->128K(1472K)
[0.345s][info][gc,heap] GC(8) Tenured: 2154K->2762K(3180K)
[0.345s][info][gc     ] GC(8) Pause Young (Allocation Failure)
   3M->2M(4M) 2.072ms
[0.368s][info][gc,heap] GC(9) DefNew: 1472K->128K(1472K)
[0.368s][info][gc,heap] GC(9) Tenured: 2762K->3044K(3180K)
[0.368s][info][gc     ] GC(9) Pause Young (Allocation Failure)
   4M->3M(4M) 1.625ms
[0.387s][info][gc     ] GC(11) Pause Full (Allocation Failure)
   3M->3M(4M) 9.019ms
[0.387s][info][gc,heap] GC(10) DefNew: 1472K->1K(2560K)
[0.387s][info][gc,heap] GC(10) Tenured: 3044K->3371K(5620K)
[0.387s][info][gc     ] GC(10) Pause Young (Allocation Failure)
   4M->3M(7M) 9.989ms
[0.430s][info][gc,heap] GC(12) DefNew: 2304K->256K(2560K)
[0.430s][info][gc,heap] GC(12) Tenured: 3371K->3425K(5620K)
[0.430s][info][gc     ] GC(12) Pause Young (Allocation Failure)
   5M->3M(7M) 3.530ms
[0.461s][info][gc,heap] GC(13) DefNew: 2560K->256K(2560K)
[0.461s][info][gc,heap] GC(13) Tenured: 3425K->3789K(5620K)
[0.461s][info][gc     ] GC(13) Pause Young (Allocation Failure)
   5M->3M(7M) 2.481ms
Step/TotalMemory/FreeMemory/UsedMemory:
   -- More Young GC and Full GC occurred in JVM start-up process
      They are unnecessary, JVM should be started with a larger heap

[0.510s][info][gc,heap] GC(14) DefNew: 2383K->255K(2560K)
[0.510s][info][gc,heap] GC(14) Tenured: 3789K->4308K(5620K)
[0.510s][info][gc     ] GC(14) Pause Young (Allocation Failure)
   6M->4M(7M) 2.915ms
1   8376320   2582304   5794016

   -- Another Young GC occurred due to my first 1MB object request
      Maybe it was too big to fit into the Survivor Space "From".

[0.538s][info][gc     ] GC(16) Pause Full (Allocation Failure)
   6M->3M(8M) 6.827ms
[0.538s][info][gc,heap] GC(15) DefNew: 2401K->0K(3136K)
[0.538s][info][gc,heap] GC(15) Tenured: 4308K->4065K(6776K)
[0.538s][info][gc     ] GC(15) Pause Young (Allocation Failure)
   6M->3M(9M) 8.840ms
2   10149888   5360456   4789432

   -- A Young GC followed by a Full GC occurred due to my 2nd object
      Heap size increased from 8M to 9M

3   10149888   4265400   5884488
4   10149888   3170344   6979544
[0.540s][info][gc,heap] GC(17) DefNew: 2750K->319K(3136K)
[0.540s][info][gc,heap] GC(17) Tenured: 4065K->6449K(6776K)
[0.540s][info][gc     ] GC(17) Pause Young (Allocation Failure)
   6M->6M(9M) 0.876ms
5   10149888   2065688   8084200

   -- Another Young GC occurred due to my 3rd and 4th objects
      Survivor Space "From" was expanded to hold 2 1MB objects

6   10149888   969912   9179976
[0.548s][info][gc     ] GC(19) Pause Full (Allocation Failure)
   9M->9M(12M) 6.105ms
[0.548s][info][gc,heap] GC(18) DefNew: 3027K->319K(6912K)
[0.548s][info][gc,heap] GC(18) Tenured: 6449K->9106K(15180K)
[0.548s][info][gc     ] GC(18) Pause Young (Allocation Failure)
   9M->9M(21M) 7.593ms
7   22622208   12393368   10228840
8   22622208   11292448   11329760
9   22622208   10191528   12430680
10   22622208   9090608   13531600
11   22622208   7989688   14632520
[0.554s][info][gc,heap] GC(20) DefNew: 6208K->703K(6912K)
[0.554s][info][gc,heap] GC(20) Tenured: 9106K->14578K(15180K)
[0.554s][info][gc     ] GC(20) Pause Young (Allocation Failure)
   14M->14M(21M) 4.421ms
12   22622208   6906968   15715240
13   22622208   5744264   16877944
14   22622208   4704136   17918072
15   22622208   3582056   19040152
16   22622208   2476376   20145832
17   22622208   1370696   21251512
[0.567s][info][gc     ] GC(22) Pause Full (Allocation Failure)
   20M->20M(26M) 7.839ms
[0.567s][info][gc,heap] GC(21) DefNew: 6686K->703K(15488K)
[0.567s][info][gc,heap] GC(21) Tenured: 14578K->20516K(34196K)
[0.567s][info][gc     ] GC(21) Pause Young (Allocation Failure)
   20M->20M(48M) 11.604ms
18   50876416   28544296   22332120
19   50876416   27351376   23525040
20   50876416   26224008   24652408
21   50876416   25162192   25714224
22   50876416   24034824   26841592
23   50876416   22956608   27919808
24   50876416   21829240   29047176
25   50876416   20767424   30108992
26   50876416   19640056   31236360
27   50876416   18561840   32314576
28   50876416   17434472   33441944
29   50876416   16372656   34503760
[0.579s][info][gc,heap] GC(23) DefNew: 13690K->1663K(15488K)
[0.579s][info][gc,heap] GC(23) Tenured: 20516K->32421K(34196K)
[0.579s][info][gc     ] GC(23) Pause Young (Allocation Failure)
   33M->33M(48M) 8.423ms

   -- More Young GC and Full GC occurred
      Heap size was expanded more and more
    More application 1MB objects can be allocated with GC interruptions.
...