"-XX:+PrintHeapAtGC" - Print Heap Summary per GC

Java 8 GC Tutorials - Herong's Tutorial Examples

∟"-XX:+PrintHeapAtGC" - Print Heap Summary per GC

This section describes the garbage collection logging option, '-XX:+PrintHeapAtGC', which prints two snapshots of the heap memory for each GC, one before the GC and another after the GC.

In this tutorial, let's try the "-XX:+PrintHeapAtGC" garbage collection logging option to see what we will get in the log file:

herong> \progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m \
   -XX:+PrintHeapAtGC -Xloggc:gc.log GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:
1   2031616   698408   1333208
2   3874816   1472824   2401992
3   3874816   424944   3449872
4   8970240   4441352   4528888
...
(Ctrl-C)

herong> more gc.log

{Heap before GC invocations=0 (full 0):
   -- invocations=0: 0 GCs (Minor and Major) have been performed
   -- full 0: 0 Major GCs have been performed
   -- Major GC is referred as Full GC in log messages

 def new generation   total 960K, used 878K [...
  eden space 896K,  98% used [...
  from space 64K,   0% used [...
  to   space 64K,   0% used [...
 tenured generation   total 1024K, used 0K [...
   the space 1024K,   0% used [...
 Metaspace used 1555K, capacity 2242K, committed 2368K, reserved 4480K
   -- The "eden" space is almost full, 98%. Time for Minor GC.

0.113: [GC (Allocation Failure)  878K->756K(1984K), 0.0016854 secs]

Heap after GC invocations=1 (full 0):
   -- 1 GCs (Minor and Major) have been performed
   -- 0 Major (referred as full here) GCs have been performed
 def new generation   total 960K, used 64K [...
  eden space 896K,   0% used [...
  from space 64K, 100% used [...
  to   space 64K,   0% used [...
 tenured generation   total 1024K, used 692K [...
   the space 1024K,  67% used [...
 Metaspace used 1555K, capacity 2242K, committed 2368K, reserved 4480K
}
   -- The Minor GC moved 64K of objects to the "from" space from "eden",
   -- and 832K of objects to the "tenured" generation
...

{Heap before GC invocations=1 (full 0):
 def new generation   total 960K, used 865K [...
  eden space 896K,  89% used [...
  from space 64K, 100% used [...
  to   space 64K,   0% used [...
 tenured generation   total 1024K, used 692K [...
   the space 1024K,  67% used [...
 Metaspace used 1555K, capacity 2242K, committed 2368K, reserved 4480K
   -- The "eden" space is almost full, 98%. Time for Minor GC again.

1.126: [GC (Allocation Failure) 1557K->1540K(2500K), 0.0027685 secs]
1.129: [Full GC (Allocation Failure) 1540K->1540K(2500K), 0.0031179 secs]
   -- Minor GC is not enough. Time for Major GC

Heap after GC invocations=2 (full 1):
   -- 2 GCs (Minor and Major) have been performed
   -- 1 Major GCs have been performed
 def new generation   total 1216K, used 0K [...
  eden space 1088K,   0% used [...
  from space 128K,   0% used [...
  to   space 128K,   0% used [...
 tenured generation   total 2568K, used 1539K [...
   the space 2568K,  59% used [...
 Metaspace used 1555K, capacity 2242K, committed 2368K, reserved 4480K
}
   -- Heap size was expanded during the GC
...

Notes on the output:

The "-XX:+PrintHeapAtGC" option did provide two snapshots of the heap usage, one before the GC and another one after the GC. This definitely helps us to understand how what the GC did to the different parts of the heap memory.
But the message size is big. So you will get a very log file if you are running a Java application for a long period of time.