Adaptive Size Policy Log Messages

Java GC Tutorials - Herong's Tutorial Examples

∟Parallel Collector - "+XX:+UseParallelGC"

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

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