7.10.2 Examples of extended verbosegc information output when Full GC occurs
This subsection explains the output of extended verbosegc information when Full GC occurs.
- Organization of this subsection
(1) An example of output when the memory size being used in the New area (total of the Eden area and the Survivor area) exceeds the unused memory size for the maximum value of the Tenured area
An example of output of extended verbosegc information is shown below. Parts that are highlighted and bolded indicate factors that contribute to Full GC occurring.
... [VGC]<Wed May 11 23:12:05 2005>[GC 27340K->27340K(32704K), 0.0432900 secs][DefNew::Eden: 3440K->0K(3456K)][DefNew::Survivor: 58K->58K(64K)][Tenured: 23841K->27282K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] [VGC]<Wed May 11 23:12:05 2005>[Full GC 30780K->30780K(32704K), 0.2070500 secs][DefNew::Eden: 3440K->1602K(3456K)][DefNew::Survivor: 58K->0K(64K)][Tenured: 27282K->29178K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] ...
The following conclusions are drawn from this output example:
-
The memory size being used in the New area (3440 K + 58 K=3498 K) has exceeded the unused memory size for the maximum value of the Tenured area (29184 K - 27282 K = 1902 K).
-
The cause of Full GC is failure to allocate the object.
(2) An example of output when copy GC fails to move objects from the New area (the Eden area and the Survivor area) to the Tenured area
The following is an output example of the extended verbosegc information. The part that is highlighted and bolded indicates a factor that contributes to Full GC occurring.
... [VGC]<Thu Oct 20 11:04:42 2011>[GC 26418K->26418K (29696K), 0.0000000 secs][DefNew::Eden:8188K->8188K(8192K)][DefNew::Survivor: 1021K->1021K(1024K)][Tenured:17208K->17208K (20480K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0000000 secs][Sys: 0.0000000 secs][IM: 877K, 1104K, 0K][TC: 9][DOE: 0K, 0] [VGC]<Thu Oct 20 11:04:42 2011>[Full GC 26418K->6450K(29696K), 0.0156250 secs][DefNew::Eden:8188K->0K(8192K)][DefNew::Survivor:1021K->0K(1024K)][Tenured:17208K->6450K(20480K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:PromotionFail][User: 0.0156250 secs][Sys: 0.0000000 secs][IM: 925K, 1104K, 0K][TC: 9][DOE: 0K, 0]
The following conclusion is drawn from this output example:
-
The cause of Full GC is failure to move objects from the New area to the Tenured area due to copy GC.
(3) An example of output when the memory size to be allocated (size of the Java objects created by new) exceeds the unused memory size of the Tenured area
An example of output of extended verbosegc information is shown below. Parts that are highlighted and bolded indicate factors that contribute to Full GC occurring.
... [VGC]<Wed May 11 23:53:18 2005>[GC 28499K->28490K(32704K), 0.0540590 secs][DefNew::Eden: 808K->0K(3456K)][DefNew::Survivor: 64K->62K(64K)][Tenured: 27626K->28428K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] [VGC]<Wed May 11 23:53:18 2005>[Full GC 28490K->8959K(32704K), 0.1510380 secs][DefNew::Eden: 0K->0K(3456K)][DefNew::Survivor: 62K->0K(64K)][Tenured: 28428K->8959K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] ...
The following conclusions are drawn from this example of output:
-
An attempt was made to create a Java object whose memory size exceeds the unused memory size of the Tenured area (29184 K - 28428 K = 756 K) with new.
-
The cause of Full GC is a failure to allocate objects.
(4) An example of output when copy GC causes the unused memory size of the Tenured area to fall below 10,000 bytes
The following is an output example of the extended verbosegc information. Parts that are highlighted and bolded indicate factors that contribute to Full GC occurring.
... [VGC]<Fri May 25 15:21:33 2007>[GC 15436K->15416K(19840K), 0.0111825 secs][DefNew::Eden: 4413K->0K(4416K)][DefNew::Survivor: 512K->509K(512K)][Tenured: 10511K->14906K(14912K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0000000 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:21:33 2007>[Full GC 15416K->8622K(19840K), 0.0284614 secs][DefNew::Eden: 0K->0K(4416K)][DefNew::Survivor: 509K->0K(512K)][Tenured: 14906K->8622K(14912K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0312500 secs][Sys: 0.0000000 secs] ...
The following conclusions are drawn from this example of output:
-
The used memory size of the Tenured area increased from 10,511 KB to 14,906 KB due to the transfer of objects from the New area to the Tenured area in the first copy GC. As a result, the unused memory size of the allocated Tenured area became 14,912 KB - 14,906 KB = 6 KB and fell below 10,000 bytes (approximately 10 K bytes).
-
The reason for the first copy GC is the object allocation failure. The first copy GC and second Full GC occur consecutively before the control returns to the Java program.
(5) An example of output when the allocated Tenured area is extended due to the transfer of objects to the Tenured area during copy GC
An example of output of extended verbosegc information is shown below. Parts that are highlighted and bolded indicate factors that contribute to Full GC occurring.
... [VGC]<Fri May 25 15:42:00 2007>[GC 12745K->10151K(15872K), 0.0048346 secs][DefNew::Eden: 4416K->0K(4416K)][DefNew::Survivor: 137K->512K(512K)][Tenured: 8192K->9639K(10944K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:42:00 2007>[GC 14563K->14536K(19072K), 0.0104957 secs][DefNew::Eden: 4412K->0K(4416K)][DefNew::Survivor: 512K->510K(512K)][Tenured: 9639K->14026K(14144K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:42:00 2007>[Full GC 14536K->8610K(19072K), 0.0287254 secs][DefNew::Eden: 0K->0K(4416K)][DefNew::Survivor: 510K->0K(512K)][Tenured: 14026K->8610K(14144K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0312500 secs][Sys: 0.0000000 secs] ...
The following conclusions are based on this example of output:
-
The Tenured area must be at least 14,026 KB or more due to the movement of objects from the New area to the Tenured area in the second copy GC. Therefore, the size of the allocated Tenured area is extended from 10,944 KB to 14,144 KB.
-
The reason for the second copy GC is object allocation failure. The second copy GC and third Full GC occur consecutively before the control returns to the Java program.
(6) An example of output when the java.lang.System.gc() method is executed in an application
An example of output of extended verbosegc information is shown below. The part that is highlighted and bolded indicates a factor that contributes to Full GC occurring.
... [VGC]<Mon Apr 18 20:36:29 2005>[Full GC 330K->150K(3520K), 0.0387690 secs][DefNew::Eden: 330K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->150K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:System.gc][User: 0.0156250 secs][Sys: 0.0312500 secs] ...
The following conclusion is drawn from this example of output:
-
The cause of Full GC is calling the java.lang.System.gc() method in J2EE applications or batch applications.
(7) An example of output when the memory size to be allocated to the Metaspace area exceeds the unused memory size of the allocated Metaspace area
An example of output of extended verbosegc information is shown below. The part that is highlighted and bolded indicates a factor that contributes to Full GC occurring.
... [VGC]<Wed Jan 07 01:56:13 2015>[Full GC 11273K->6037K(15872K), 0. 0060004 secs][DefNew::Eden: 442K->0K(4416K)][DefNew::Survivor: 512K->0K(512K)][Tenured: 10319K->6037K(10944K)][Metaspace: 22811K(24520K, 24576K)->22811K(24520K, 24576K)][class space: 10758K(10988K, 11008K)->10758K(10988K, 11008K)][cause:MetaspaceAllocFail][User: 0.0312002 secs][Sys: 0.0000000 secs] ...
The following conclusions are drawn from this example of output:
-
The memory size to be allocated to the Metaspace area exceeded the unused memory size of the allocated Metaspace area (24576 K - 22811 K = 1765 K).
-
Full GC was caused by a failure to allocate sufficient memory to the Metaspace heap.
(8) An example of output for the case when the javagc command is executed
An example of output of extended verbosegc information is shown below. The part that is highlighted and bolded indicates a factor that contributes to Full GC occurring.
... [VGC]<Mon Apr 18 21:46:50 2005>[Full GC 369K->189K(3520K), 0.0403010 secs][DefNew::Eden: 369K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->189K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:JavaGC Command][User: 0.0156250 secs][Sys: 0.0312500 secs] ...
The following conclusion is drawn from this example of output:
-
The cause of Full GC is execution of the javagc command.
(9) An example of output for the case when the jheapprof command is executed
An example of output of extended verbosegc information is shown below. The part that is highlighted and bolded indicates a factor that contributes to Full GC occurring.
... [VGC]<Mon Apr 18 21:46:50 2005>[Full GC 369K->189K(3520K), 0.0403010 secs][DefNew::Eden: 369K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->189K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:JHeapProf Command][User: 0.0156250 secs][Sys: 0.0312500 secs] ...
The following conclusion is drawn from this example of output:
-
The cause of Full GC is execution of the jheapprof command.