Adaptive Size Policy Log Messages

This section provides examples and explanations of log messages generated '-Xlog:gc+ergo=debug' and '-XX:AdaptiveSizePolicyOutputInterval=1' JVM options used with the Parallel collector.

As we described in the previous section, the "Adaptive Size Policy" feature supported by the Parallel collector dynamically changes generation sizes to meet application performance goals.

Before we do any further tests, let's run our test program GarbageCollection2.java again with "-Xlog:gc+ergo=debug" and "-XX:AdaptiveSizePolicyOutputInterval=1" JVM options to see what we can get from the log messages:

C:\herong>java -Xms1200m -Xmx1200m -XX:NewRatio=1 -XX:SurvivorRatio=1
   -XX:+UseParallelGC -Xlog:gc=debug,gc+heap=debug,gc+ergo=debug
   -XX:AdaptiveSizePolicyOutputInterval=1
   GarbageCollection2

Step/TotalMemory/FreeMemory/UsedMemory:
1   1048576000   1019201136   29374864
...
172   1048576000   839891904   208684096
[debug][gc,heap] GC(0) Heap before GC invocations=1 (full 0): PSYoungGen...
[debug][gc,heap] GC(0)   eden space 204800K, 99% used [...
[debug][gc,heap] GC(0)   from space 204800K, 0% used [...
[debug][gc,heap] GC(0)   to   space 204800K, 0% used [...
[debug][gc,heap] GC(0)  ParOldGen       total 614400K, used 0K [...
[debug][gc,heap] GC(0)   object space 614400K, 0% used [...

   -- Message generated by -Xlog:gc+ergo=debug
[debug][gc,ergo] GC(0) AdaptiveSizeStart:  collection: 1
[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size
                       limits: desired_eden_size: 419430400
					   old_eden_size: 209715200 eden_limit: 209715200
					   cur_eden: 209715200 max_eden_size: 209715200
					   avg_young_live: 35652144
[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size:
                       costs minor_time: 0.019342 major_cost: 0.000000
					   mutator_cost: 0.980658 throughput_goal: 0.990000
[debug][gc,ergo] GC(0) Live_space: 304087616 free_space: 419430400
[debug][gc,ergo] GC(0) Old eden_size: 209715200 desired_eden_size: 209715200
[debug][gc,ergo] GC(0) AdaptiveSizeStop: collection: 1

[info ][gc,heap] GC(0) PSYoungGen: 203793K->34816K(409600K)
[info ][gc,heap] GC(0) ParOldGen: 0K->16K(614400K)
[info ][gc     ] GC(0) Pause Young (Allocation Failure)
                       199M->34M(1000M) 11.677ms
[debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0): PSYoungGen...
[debug][gc,heap] GC(0)   eden space 204800K, 0% used [...
[debug][gc,heap] GC(0)   from space 204800K, 17% used [...
[debug][gc,heap] GC(0)   to   space 204800K, 0% used [...
[debug][gc,heap] GC(0)  ParOldGen       total 614400K, used 16K [...
[debug][gc,heap] GC(0)   object space 614400K, 0% used [...

    -- Extra message generated by -XX:AdaptiveSizePolicyOutputInterval=1
[debug][gc,ergo] GC(0) UseAdaptiveSizePolicy actions to meet
                       *** throughput goal ***
[debug][gc,ergo] GC(0)                   GC overhead (%)
[debug][gc,ergo] GC(0)   Young generation:    1.93  (attempted to grow)
[debug][gc,ergo] GC(0)   Tenured generation:  0.00  (no change)
...

Let's take a closer look at the "Adaptive Size" collection message:

[debug][gc,ergo] GC(0) AdaptiveSizeStart:  collection: 1
[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size limits:
   desired_eden_size: 419430400 old_eden_size: 209715200
   eden_limit: 209715200 cur_eden: 209715200
   max_eden_size: 209715200 avg_young_live: 35652144
[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size:
   costs minor_time: 0.019342 major_cost: 0.000000
   mutator_cost: 0.980658 throughput_goal: 0.990000
[debug][gc,ergo] GC(0) Live_space: 304087616 free_space: 419430400
[debug][gc,ergo] GC(0) Old eden_size: 209715200 desired_eden_size: 209715200
[debug][gc,ergo] GC(0) AdaptiveSizeStop: collection: 1

Here is a detailed explanation of each line in the message:

[debug][gc,ergo] GC(0) AdaptiveSizeStart:  collection: 1
   -- Collection #1 started

[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size limits:
   desired_eden_size: 419430400 old_eden_size: 209715200
   eden_limit: 209715200 cur_eden: 209715200
   max_eden_size: 209715200 avg_young_live: 35652144
   -- Suggested to increase "eden" to 419430400 based on space analysis

[debug][gc,ergo] GC(0) PSAdaptiveSizePolicy::compute_eden_space_size:
   costs minor_time: 0.019342 major_cost: 0.000000
   mutator_cost: 0.980658 throughput_goal: 0.990000
   -- Summary of the current costs and goal.

[debug][gc,ergo] GC(0) Live_space: 304087616 free_space: 419430400
   -- Not sure where the live space came from

[debug][gc,ergo] GC(0) Old eden_size: 209715200 desired_eden_size: 209715200
   -- Suggested to keep "eden" as 209715200 based on GC time cost

[debug][gc,ergo] GC(0) AdaptiveSizeStop: collection: 1
   -- Collection #1 started

Let's take a closer look at the "Adaptive Size" collection message:

[debug][gc,ergo] GC(0) UseAdaptiveSizePolicy actions to meet
                       *** throughput goal ***
[debug][gc,ergo] GC(0)                   GC overhead (%)
[debug][gc,ergo] GC(0)   Young generation:    1.93  (attempted to grow)
[debug][gc,ergo] GC(0)   Tenured generation:  0.00  (no change)

Here is a detailed explanation of each line in the message:

[debug][gc,ergo] GC(0) UseAdaptiveSizePolicy actions to meet
                       *** throughput goal ***
   -- Decided to meet Throughput goal

[debug][gc,ergo] GC(0)                    GC overhead (%)
[debug][gc,ergo] GC(0)     Young generation:  1.93  (attempted to grow)
   -- Minor GC time percentage so far: 3.38%
   -- Which is above the default desire level of 1%
   -- Decided to increase Young generation to reduce GC time

[debug][gc,ergo] GC(0)     Tenured generation:      0.00	  (no change)
   -- Major GC time percentage so far: 0.00%
   -- Decided to keep Tenured generation size

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