"-Xlog:gc+heap=trace" - GC+HEAP Log Messages

This section describes the garbage collection logging option, '-Xlog:gc+heap=trace', which prints two snapshots of the heap of each GC, one before the GC and another after the GC. It also prints heap changes of each GC.

In this tutorial, let's try the "-Xlog:gc+heap=trace" garbage collection logging option to see what we will get in the log file:

herong> java -Xms2m -Xmx64m -Xlog:gc+heap=trace: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
[0.011s][info][gc,heap] Heap region size: 1M
   -- Default region size is 1M for each heap region
[0.011s][debug][gc,heap] Minimum heap 2097152  Initial heap 2097152
   Maximum heap 67108864
   -- Heap starts with 2 regions

[0.056s][debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0):
   garbage-first heap   total 2048K, used 1024K [...
[0.056s][debug][gc,heap] GC(0)   region size 1024K, 1 young (1024K),
   0 survivors (0K)
[0.056s][debug][gc,heap] GC(0) Metaspace    used 325K, capacity 4515K,
   committed 4864K, reserved 1056768K
[0.056s][debug][gc,heap] GC(0)  class space used 30K, capacity 398K,
   committed 512K, reserved 1048576K
   -- Heap status before GC #1

[0.058s][info ][gc,heap] GC(0) Eden regions: 1->0(1)
[0.058s][trace][gc,heap] GC(0)  Used: 0K, Waste: 0K
[0.058s][info ][gc,heap] GC(0) Survivor regions: 0->1(1)
[0.058s][trace][gc,heap] GC(0)  Used: 566K, Waste: 457K
[0.059s][info ][gc,heap] GC(0) Old regions: 0->0
[0.059s][trace][gc,heap] GC(0)  Used: 0K, Waste: 0K
[0.059s][info ][gc,heap] GC(0) Archive regions: 0->0
[0.059s][trace][gc,heap] GC(0)  Used: 0K, Waste: 0K
[0.059s][info ][gc,heap] GC(0) Humongous regions: 0->0
[0.059s][trace][gc,heap] GC(0)  Used: 0K, Waste: 0K
   -- What was done in GC #1

[0.059s][debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
   garbage-first heap   total 2048K, used 566K [...
[0.059s][debug][gc,heap] GC(0)   region size 1024K, 1 young (1024K),
   1 survivors (1024K)
[0.059s][debug][gc,heap] GC(0) Metaspace    used 325K, capacity 4515K,
   committed 4864K, reserved 1056768K
[0.059s][debug][gc,heap] GC(0)  class space used 30K, capacity 398K,
   committed 512K, reserved 1048576K
   -- Heap status after GC #1

[0.113s][debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0...
[0.113s][debug][gc,heap] GC(1)   region size 1024K, 2 young (2048K)...
[0.113s][debug][gc,heap] GC(1)  Metaspace       used 1344K, capacit...
[0.113s][debug][gc,heap] GC(1)   class space    used 160K, capacity...
[0.115s][info ][gc,heap] GC(1) Eden regions: 1->0(1)
   -- Heap status before GC #2

[0.115s][trace][gc,heap] GC(1)  Used: 0K, Waste: 0K
[0.115s][info ][gc,heap] GC(1) Survivor regions: 1->1(1)
[0.116s][trace][gc,heap] GC(1)  Used: 457K, Waste: 566K
[0.116s][info ][gc,heap] GC(1) Old regions: 0->1
[0.116s][trace][gc,heap] GC(1)  Used: 545K, Waste: 478K
[0.116s][info ][gc,heap] GC(1) Archive regions: 0->0
[0.116s][trace][gc,heap] GC(1)  Used: 0K, Waste: 0K
[0.116s][info ][gc,heap] GC(1) Humongous regions: 0->0
[0.116s][trace][gc,heap] GC(1)  Used: 0K, Waste: 0K
   -- What was done in GC #2

[0.116s][debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0)...
[0.116s][debug][gc,heap] GC(1)   region size 1024K, 1 young (1024K)...
[0.116s][debug][gc,heap] GC(1)  Metaspace       used 1344K, capacit...
[0.116s][debug][gc,heap] GC(1)   class space    used 160K, capacity...
   -- Heap status after GC #2

...

The log messages show that the "-Xlog:gc+heap=trace" option provides 3 chunks of information for each GC instance:

Obviously, "--Xlog:gc+heap=trace" option is very useful to understand how each GC is performed.

Table of Contents

 About This Book

 Heap Memory Area and Size Control

JVM Garbage Collection Logging

 Garbage Collection Demo Program

 Garbage Collection Logging Options

 "-Xlog:gc" - Default GC Logging Level: INFO

 "-Xlog:gc=trace" - Lowest GC Logging Level: TRACE

"-Xlog:gc+heap=trace" - GC+HEAP Log Messages

 "-Xlog:gc*=trace" - Maximum GC Logging

 "-XX:+PrintFlagsFinal" - Print JVM Options

 Introduction of Garbage Collectors

 Serial Collector - "+XX:+UseSerialGC"

 Parallel Collector - "+XX:+UseParallelGC"

 Concurrent Mark-Sweep (CMS) Collector - "+XX:+UseConcMarkSweepGC"

 Garbage First (G1) Collector - "+XX:+UseG1GC"

 The Z Garbage Collector (ZGC) - "+XX:+UseZGC"

 Object References and Garbage Collection

 Garbage Collection Performance Test Program

 Performance Tests on Serial Collector

 Performance Tests on Parallel collector

 Performance Tests on Concurrent collector

 Performance Tests on G1 collector

 Garbage Collection Performance Test Summary

 References

 Full Version in PDF/EPUB