"-Xlog:gc+ergo=trace" - Minor GC Report

This section provides examples of log messages generated from '--Xlog:gc+ergo=trace' that tells us what happened at each Parallel Minor GC.

From last tutorial, we learned that the "-Xlog:gc+ergo=debug" option generates adaptive heap size related log messages at the DEBUG level. If we lower it to the TRACE level, additional log messages will be generated to help us to learn more about how Minor GC is performed.

For example, if we run GarbageCollection2.java with the following JVM options, we can get enough log messages to figure what happened at each Minor GC:

C:\herong>java -Xms400m -Xmx400m -XX:+UseParallelGC
   -Xlog:gc=debug,gc+heap=debug,gc+ergo=trace GarbageCollection2

Here is what happened at GC(0), a Minor GC:

...
74   402128896   298309936   103818960
[debug][gc,heap] GC(0) Heap before GC invocations=1 (full 0): PSYoungGen
                         total 119296K, used 101385K [...
   -- 101385K bytes newly allocated in "eden" before GC						
						
[debug][gc,heap] GC(0)   eden space 102400K, 99% used [...
[debug][gc,heap] GC(0)   from space 16896K, 0% used [...
[debug][gc,heap] GC(0)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(0)  ParOldGen       total 273408K, used 0K [...
[debug][gc,heap] GC(0)   object space 273408K, 0% used [...

[trace][gc,ergo] GC(0) AdaptiveSizePolicy::minor_collection_end:
                         minor gc cost: 0.021436  average: 0.021436
                         minor pause: 11.664955 minor period 532.523284
   -- Minor GC ended and application paused for about 11 ms.

[trace][gc,ergo] GC(0) AdaptiveSizePolicy::update_averages:
                       survived: 16711952  promoted: 18891040
					   overflow: false
   -- 16711952 bytes survived in "from" space
   -- 18891040 bytes promoted to Tenured generation
   -- Bytes removed: 101385K - 16711952 - 18891040 = 68215248 bytes
   -- Bytes in Tenured generation: 0 + 18891040 = 18891040 bytes = 18448K
   						
...
[info ][gc,heap] GC(0) PSYoungGen: 101385K->16320K(119296K)
[info ][gc,heap] GC(0) ParOldGen: 0K->18448K(273408K)
   -- Young generation usage reduced. Old generation usage expanded.

[info ][gc     ] GC(0) Pause Young (Allocation Failure)
                       99M->33M(383M) 12.294ms
[debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0): PSYoungGen
                         total 119296K, used 16320K [...
[debug][gc,heap] GC(0)   eden space 102400K, 0% used [...
[debug][gc,heap] GC(0)   from space 16896K, 96% used [...
[debug][gc,heap] GC(0)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(0)  ParOldGen       total 273408K, used 18448K [...
[debug][gc,heap] GC(0)   object space 273408K, 6% used [...

Here is what happened at GC(1), a Minor GC:

...
172   402128896   261709136   140419760
[debug][gc,heap] GC(1) Heap before GC invocations=2 (full 0): PSYoungGen
                         total 119296K, used 118680K [...
   -- 118680K bytes newly allocated in "eden" before GC

[debug][gc,heap] GC(1)   eden space 102400K, 99% used [...
[debug][gc,heap] GC(1)   from space 16896K, 96% used [...
[debug][gc,heap] GC(1)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(1)  ParOldGen       total 273408K, used 18448K [...
[debug][gc,heap] GC(1)   object space 273408K, 6% used [...

[trace][gc,ergo] GC(1) AdaptiveSizePolicy::minor_collection_end:
                         minor gc cost: 0.371056  average: 0.196423
                         minor pause: 9.135286 minor period 15.484390
   -- Minor GC ended and application paused for about 9 ms.

[trace][gc,ergo] GC(1) AdaptiveSizePolicy::update_averages:
                       survived: 16728352  promoted: 19931440
					   overflow: false
   -- 16728352 bytes survived in "from" space
   -- 19931440 bytes promoted to Tenured generation
   -- Bytes removed: 118680K - 16728352 - 19931440 = 84868528 bytes
   -- Bytes in Tenured generation: 18891040 + 19931440
      = 38822480 bytes = 37912K			
						
[info ][gc,heap] GC(1) PSYoungGen: 118680K->16336K(119296K)
[info ][gc,heap] GC(1) ParOldGen: 18448K->37912K(273408K)
[info ][gc     ] GC(1) Pause Young (Allocation Failure)
                       133M->52M(383M) 9.687ms
   -- Young generation usage reduced. Old generation usage expanded.

[debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0): PSYoungGen
                        total 119296K, used 16336K [...
[debug][gc,heap] GC(1)   eden space 102400K, 0% used [...
[debug][gc,heap] GC(1)   from space 16896K, 96% used [...
[debug][gc,heap] GC(1)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(1)  ParOldGen       total 273408K, used 37912K [...
[debug][gc,heap] GC(1)   object space 273408K, 13% used [...

Here is what happened at GC(15), a Full GC:

[debug][gc,heap] GC(15) Heap before GC invocations=16 (full 1): PSYoungGen
                          total 119296K, used 16384K [...
[debug][gc,heap] GC(15)   eden space 102400K, 0% used [...
[debug][gc,heap] GC(15)   from space 16896K, 96% used [...
[debug][gc,heap] GC(15)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(15)  ParOldGen       total 273408K, used 263105K [...
[debug][gc,heap] GC(15)   object space 273408K, 96% used [...

[trace][gc,ergo] GC(15) psAdaptiveSizePolicy::major_collection_end:
                          major gc cost: 0.018823  average: 0.018823
                          major pause: 15.877642 major period 827.628856
   -- Major GC ended and application paused for about 15 ms.

[debug][gc] GC(15) Shrinking ParOldGen from 273408K by 110080K to 163328K
   -- Old generation allocation shrinked, decided by AdaptiveSizePolicy

[info ][gc,heap] GC(15) PSYoungGen: 16384K->0K(119296K)
[info ][gc,heap] GC(15) ParOldGen: 263105K->34622K(163328K)
[info ][gc     ] GC(15) Pause Full (Ergonomics) 272M->33M(276M) 24.506ms
   -- Young generation usage reduced. Old generation usage reduced.

[debug][gc,heap] GC(15) Heap after GC invocations=16 (full 1): PSYoungGen
                          total 119296K, used 0K [...
[debug][gc,heap] GC(15)   eden space 102400K, 0% used [...
[debug][gc,heap] GC(15)   from space 16896K, 0% used [...
[debug][gc,heap] GC(15)   to   space 16896K, 0% used [...
[debug][gc,heap] GC(15)  ParOldGen       total 163328K, used 34622K [...
[debug][gc,heap] GC(15)   object space 163328K, 21% used [...

Table of Contents

 About This Book

 Heap Memory Area and Size Control

 JVM Garbage Collection Logging

 Introduction of Garbage Collectors

 Serial Collector - "+XX:+UseSerialGC"

Parallel Collector - "+XX:+UseParallelGC"

 What Is Parallel Collector

 Parallel Collector GC Log Message Format

 Log Message Types from Parallel Collector

 "--Xlog:gc+task+time=debug" - Print GC Threads

 "-XX:ParallelGCThreads" - # of Threads

 Parallel Collector Stops Application for Minor/Major GC

 PSYoungGen Collector Using Tenuring Age

 Parallel Collector Changing NewRatio and SurvivorRatio

 Parallel Collector Adaptive Size Policy

 Adaptive Size Policy Log Messages

"-Xlog:gc+ergo=trace" - Minor GC Report

 Adaptive Size Policy Changed Survivor Space

 Adaptive Size Policy Changed Eden Space

 Adaptive Size Policy for Best Latency

 Parallel Collector Stopped using Young Generation

 Adaptive Size Policy for Best Throughput

 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