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

Java GC Tutorials - Herong's Tutorial Examples

∟Parallel Collector - "+XX:+UseParallelGC"

∟"-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:

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 shrank, 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 [...