GC Log Messages on GarbageCollection.java

JVM Tutorials - Herong's Tutorial Examples

∟Memory Management and Garbage Collectors

∟GC Log Messages on GarbageCollection.java

This section provides a tutorial example on how to read HotSpot Garbage Collection (GC) log messages generated while running GarbageCollection.java.

In the previous section, we learned how to read the Garbage Collection (GC) log messages. Now let's go back to analyze the GC log output generate from my sample program, GarbageCollection.java:

C:\>\progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m -XX:+UseSerialGC
   -XX:+PrintGCDetails GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:

   [GC (Allocation Failure) 
      0.054: [DefNew: 649K->64K(960K), 0.0008674 secs] 
      649K->505K(1984K), 0.0009833 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   -- Minor GC occurred before my application object requests
      Some small objects were deallocated. 

1   2031616   697016   1334600

   [GC (Allocation Failure) 
      1.055: [DefNew: 861K->64K(960K), 0.0008510 secs]
      1.056: [Tenured: 1226K->1279K(1280K), 0.0009817 secs]
      1303K->1290K(2240K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0019995 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   -- Full GC occurred after my first 1MB objects allocated
      All of my objects were promoted to the Tenured Generation.
      Maybe they are too big to fit into the Survivor Space "From".
      Total Heap size expanded from 1984K to 2240K.
      This full GC is unnecessary, there is no dead objects.

   [GC (Allocation Failure) 
      1.058: [DefNew: 959K->44K(1024K), 0.0007910 secs]
      1.059: [Tenured: 2176K->2220K(2264K), 0.0010183 secs] 
      2239K->2220K(3288K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0019576 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   -- Full GC occurred while allocating my second 1MB objects
      Total Heap size expanded from 2240K to 4480K.
      This full GC is unnecessary, there is no dead objects.

2   5562368   3165200   2397168
3   5562368   2102496   3459872

   [GC (Allocation Failure) 
      3.061: [DefNew: 1414K->128K(1728K), 0.0025871 secs] 
      3634K->3626K(5432K), 0.0027478 secs] 
   [Times: user=0.02 sys=0.00, real=0.00 secs] 

4   5562368   1044192   4518176

   [GC (Allocation Failure) 
      4.065: [DefNew: 1681K->127K(1728K), 0.0028974 secs]
      4.068: [Tenured: 5051K->5131K(5132K), 0.0047765 secs] 
      5180K->5179K(6860K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0079619 secs] 
   [Times: user=0.00 sys=0.00, real=0.01 secs] 

5   12759040   7172472   5586568
6   12759040   6102856   6656184
7   12759040   5044920   7714120
8   12759040   3975304   8783736

   [GC (Allocation Failure) 
      8.076: [DefNew: 3445K->384K(3904K), 0.0076061 secs] 
      8577K->8571K(12460K), 0.0077700 secs] 
   [Times: user=0.00 sys=0.00, real=0.01 secs] 

 9   12759040   2915456    9843584
10   12759040   1849336   10909704
11   12759040    783216   11975824

   [GC (Allocation Failure) 
      11.085: [DefNew: 3763K->383K(3904K), 0.0061186 secs]
      11.091: [Tenured: 11564K->11543K(11664K), 0.0133593 secs] 
      11951K->11927K(15568K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0197676 secs] 
   [Times: user=0.02 sys=0.00, real=0.02 secs] 
   -- Full GC occurred again unnecessarily and costed 0.02 seconds

12   28614656   15596144   13018512
13   28614656   14529376   14085280
14   28614656   13462608   15152048
15   28614656   12395840   16218816
16   28614656   11329072   17285584
17   28614656   10262304   18352352
18   28614656    9195536   19419120

   [GC (Allocation Failure) 
      18.108: [DefNew: 7676K->959K(8704K), 0.0137197 secs] 
      19220K->19208K(27944K), 0.0138836 secs] 
   [Times: user=0.01 sys=0.00, real=0.01 secs] 

19   28614656   8136048   20478608
20   28614656   7064672   21549984
21   28614656   6007664   22606992
22   28614656   4936288   23678368
23   28614656   3879280   24735376
24   28614656   2807904   25806752
25   28614656   1736528   26878128

   [GC (Allocation Failure) 
      25.123: [DefNew: 8511K->959K(8704K), 0.0127368 secs]
      25.136: [Tenured: 25785K->25785K(25844K), 0.0173945 secs] 
      26760K->26745K(34548K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0305319 secs] 
   [Times: user=0.03 sys=0.00, real=0.03 secs] 
   -- Another unnecessary Full GC costed 0.03 seconds

26   63868928   35937368   27931560
27   63868928   34852536   29016392
28   63868928   33784104   30084824
29   63868928   32715672   31153256
30   63868928   31675672   32193256
31   63868928   30590840   33278088
32   63868928   29522408   34346520
33   63868928   28453976   35414952
34   63868928   27413976   36454952
35   63868928   26345544   37523384
36   63868928   25260712   38608216
37   63868928   24192280   39676648
38   63868928   23123848   40745080
39   63868928   22083848   41785080
40   63868928   21015416   42853512
41   63868928   19930584   43938344

   [GC (Allocation Failure) 
      41.161: [DefNew: 17122K->2112K(19392K), 0.0271571 secs] 
      42908K->42876K(62372K), 0.0272993 secs] 
   [Times: user=0.03 sys=0.00, real=0.03 secs] 

42   63868928   18898056   44970872
43   63868928   17804840   46064088
44   63868928   16739144   47129784
45   63868928   15673448   48195480
46   63868928   14607752   49261176
47   63868928   13542056   50326872
48   63868928   12476360   51392568
49   63868928   11410664   52458264
50   63868928   10344968   53523960
51   63868928    9279272   54589656
52   63868928    8213576   55655352
53   63868928    7147880   56721048
54   63868928    6082184   57786744
55   63868928    5016488   58852440
56   63868928    3950792   59918136
57   63868928    2885096   60983832

   [GC (Allocation Failure) 
      57.191: [DefNew: 19302K->19302K(19392K), 0.0000888 secs]
      57.191: [Tenured: 40764K->34956K(42980K), 0.0400130 secs] 
      60066K->34956K(62372K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0402912 secs] 
   [Times: user=0.05 sys=0.00, real=0.04 secs] 
   -- First Full GC that dealloacted my dead objects
      But the Minor GC did not free up any space. Why?

58   64880640   28542872   36337768
59   64880640   27476696   37403944
...
74   64880640   11456376   53424264

   [GC (Allocation Failure) 
      74.234: [DefNew: 17471K->17471K(19648K), 0.0000740 secs]
      74.234: [Tenured: 34956K->34700K(43712K), 0.0348190 secs] 
      52428K->34700K(63360K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0350861 secs] 
   [Times: user=0.03 sys=0.00, real=0.03 secs]
   -- Minor GC did not free up any space.

75   64880640   28541696   36338944
76   64880640   27457944   37422696
...
91   64880640   11459336   53421304

   [GC (Allocation Failure) 
      91.272: [DefNew: 17468K->17468K(19648K), 0.0000925 secs]
      91.272: [Tenured: 34700K->32474K(43712K), 0.0403216 secs] 
      52169K->32474K(63360K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0408209 secs] 
   [Times: user=0.05 sys=0.00, real=0.04 secs] 
   -- Minor GC did not free up any space.

 92   64880640   30559392   34321248
 93   64880640   29475640   35405000
...
107   64880640   14544384   50336256

   [GC (Allocation Failure) 
      107.314: [DefNew (promotion failed) : 17450K->19626K(19648K), 
         0.0356832 secs]
      107.350: [Tenured: 43711K->33242K(43712K), 0.0251411 secs] 
      49924K->33242K(63360K), 
      [Metaspace: 44K->44K(4480K)], 
      0.0610121 secs] 
   [Times: user=0.06 sys=0.00, real=0.06 secs] 
   -- Minor GC did not free up any space and failed. Why?

...

Last update: 2014.

Table of Contents

About This Book

Downloading and Installing JDK 1.8.0 on Windows

Downloading and Installing JDK 1.7.0 on Windows

java.lang.Runtime Class - The JVM Instance

java.lang.System Class - The Operating System

ClassLoader Class - Class Loaders

Class Class - Class Reflections

Sun's JVM - Java HotSpot VM

JRockit JVM 28.2.7 by Oracle Corporation

JVM Runtime Data Areas