"-XX:+PrintGC" - GC Logging Option for Short Messages

Java 8 GC Tutorials - Herong's Tutorial Examples

∟"-XX:+PrintGC" - GC Logging Option for Short Messages

This section describes the garbage collection logging option, '-XX:+PrintGC', which prints a shot message after each garbage collection is done.

In the first test, let's try the "-XX:+PrintGC" 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:+PrintGC \
   -Xloggc:gc.log GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:
1   2031616   698848   1332768
2   3874816   1473392   2401424
3   3874816   425688   3449128
4   8970240   4442016   4528224
...
(Ctrl-C)

herong> more gc.log
Java HotSpot(TM) Client VM (25.45-b02) for windows-x86
   JRE (1.8.0_45-b15), built on Apr 30 2015 12:31:00
Memory: 4k page, physical 3931768k(1490828k free),
   swap 7861660k(3414348k free)
CommandLine flags: -XX:InitialHeapSize=2097152 -XX:MaxHeapSize=67108864
   -XX:+PrintGC -XX:+PrintGCTimeStamps
   -XX:-UseLargePagesIndividualAllocation

0.093: [GC (Allocation Failure)  889K->755K(1984K), 0.0011219 secs]
1.092: [GC (Allocation Failure)  1557K->1540K(2500K), 0.0028837 secs]
1.095: [Full GC (Allocation Failure)  1540K->1540K(2500K), 0.0043869 secs]
2.095: [GC (Allocation Failure)  2601K->2580K(3784K), 0.0029118 secs]
3.097: [GC (Allocation Failure)  3624K->3620K(4820K), 0.0032433 secs]
3.101: [Full GC (Allocation Failure)  3620K->3620K(4820K), 0.0041250 secs]
5.113: [GC (Allocation Failure)  5991K->5957K(8760K), 0.0060028 secs]
7.121: [GC (Allocation Failure)  8392K->8357K(10964K), 0.0073853 secs]
...
142.218: [Full GC (Allocation Failure)
   50702K->32990K(63360K), 0.0369557 secs]
159.386: [Full GC (Allocation Failure)
   50438K->32734K(63360K), 0.0275702 secs]
176.528: [Full GC (Allocation Failure)
   50206K->32478K(63360K), 0.0325556 secs]
192.653: [GC (Allocation Failure) , 0.0272988 secs]
192.681: [Full GC (Allocation Failure)
   63329K->33246K(63360K), 0.0270574 secs]
209.760: [Full GC (Allocation Failure)
   50693K->32990K(63360K), 0.0311641 secs]
226.828: [Full GC (Allocation Failure)
   50442K->32734K(63360K), 0.0283866 secs]
...

Notice that two JVM options "-XX:+PrintGCTimeStamps" and "-XX:-UseLargePagesIndividualAllocation" are added by default.

JVM supports multiple garbage collectors and each garbage collector uses different log message format. I will explain how to read log messages later when we have better understandings on how each garbage collector works.