Adaptive Size Policy Log Messages

Java 8 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 '-XX:AdaptiveSizePolicyOutputInterval=1' and 'PrintAdaptiveSizePolicy' 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 "-XX:AdaptiveSizePolicyOutputInterval=1" and "-XX:+PrintAdaptiveSizePolicy" JVM options to read their log messages:

herong> \progra~1\java\jdk1.8.0\bin\java -XX:+UseParallelGC \
   -Xms1200m -Xmx1200m -XX:NewRatio=1 -XX:SurvivorRatio=1 \
   -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC \
   -XX:+PrintGCApplicationStoppedTime \
   -XX:+PrintGCApplicationConcurrentTime \
   -XX:AdaptiveSizePolicyOutputInterval=1 \
   -XX:+PrintAdaptiveSizePolicy \
   -XX:+PrintFlagsFinal GarbageCollection2

   -- Checking JVM options:
[Global flags]
    ...
    uintx MaxGCPauseMillis                          = 4294967295
    uintx GCTimeRatio                               = 99
     bool UseAdaptiveSizePolicy                     = true

Step/TotalMemory/FreeMemory/UsedMemory:
1   1048576000   1040187216   8388784
...
389   1048576000   820825024   227750976
0.317: Application time: 0.0304321 seconds
   -- End of application execution time

   -- Message generated by -XX:AdaptiveSizePolicyOutputInterval=1
    UseAdaptiveSizePolicy actions to meet  *** throughput goal ***
                       GC overhead (%)
    Young generation:        3.38	  (attempted to grow)
    Tenured generation:      0.00	  (no change)
    Tenuring threshold:
       (attempted to decrease to avoid survivor space overflow) = 7

{Heap before GC invocations=2 (full 0):
 PSYoungGen      total 409600K, used 222409K [...
  eden space 204800K, 99% used [0x2a000000,0x367ec300,0x36800000)
  from space 204800K, 8% used [0x36800000,0x37946140,0x43000000)
  to   space 204800K, 0% used [0x43000000,0x43000000,0x4f800000)
 ParOldGen       total 614400K, used 4K [...
  object space 614400K, 0% used [0x04800000,0x04801000,0x2a000000)
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K

0.318: [GC (Allocation Failure)

   -- Message generated by -XX:+PrintAdaptiveSizePolicy
   AdaptiveSizePolicy::update_averages:  survived: 19145040
      promoted: 4096  overflow: false
   AdaptiveSizeStart: 0.327 collection: 2
   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: 18628936
   PSAdaptiveSizePolicy::compute_eden_space_size:
      costs minor_time: 0.132738 major_cost: 0.000000
      mutator_cost: 0.867262 throughput_goal: 0.990000
      live_space: 287064392 free_space: 419430400
      old_eden_size: 209715200 desired_eden_size: 209715200
   AdaptiveSizeStop: collection: 2

[PSYoungGen: 222409K->18696K(409600K)]
   222413K->18704K(1024000K), 0.0096288 secs]
Heap after GC invocations=2 (full 0):
 PSYoungGen      total 409600K, used 18696K [...
  eden space 204800K, 0% used [0x2a000000,0x2a000000,0x36800000)
  from space 204800K, 9% used [0x43000000,0x44242150,0x4f800000)
  to   space 204800K, 0% used [0x36800000,0x36800000,0x43000000)
 ParOldGen       total 614400K, used 8K [...
  object space 614400K, 0% used [0x04800000,0x04802000,0x2a000000)
 Metaspace used 1567K, capacity 2242K, committed 2368K, reserved 4480K
}
0.328: Total time for which application threads were stopped: 0.0102265 s
   -- Second Minor GC completed
...

Let's take a closer look at the message generated by "-XX:AdaptiveSizePolicyOutputInterval=1":

    UseAdaptiveSizePolicy actions to meet  *** throughput goal ***
                       GC overhead (%)
    Young generation:        3.38	  (attempted to grow)
    Tenured generation:      0.00	  (no change)
    Tenuring threshold:
       (attempted to decrease to avoid survivor space overflow) = 7

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

    UseAdaptiveSizePolicy actions to meet  *** throughput goal ***
   -- Decided to meet Footprint goal

                       GC overhead (%)
    Young generation:        3.38	  (attempted to grow)
   -- Minor GC time percentage so far: 3.38%
      Above the default desire level of 1%
   -- Decided to increase Young generation to reduce GC time

    Tenured generation:      0.00	  (no change)
   -- Major GC time percentage so far: 0.00%
   -- Decided to keep Tenured generation size

    Tenuring threshold:
       (attempted to decrease to avoid survivor space overflow) = 7
   -- Current tenuring threshold: 7
   -- Decided lower it

Now let's look at the message generated by "-XX:+PrintAdaptiveSizePolicy":

   AdaptiveSizePolicy::update_averages:  survived: 19145040
      promoted: 4096  overflow: false
   AdaptiveSizeStart: 0.327 collection: 2
   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: 18628936
   PSAdaptiveSizePolicy::compute_eden_space_size:
      costs minor_time: 0.132738 major_cost: 0.000000
      mutator_cost: 0.867262 throughput_goal: 0.990000
      live_space: 287064392 free_space: 419430400
      old_eden_size: 209715200 desired_eden_size: 209715200
   AdaptiveSizeStop: collection: 2

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

   AdaptiveSizePolicy::update_averages:  survived: 19145040
      promoted: 4096  overflow: false
   -- 19145K survived in "from" space
   -- 4K promoted to Tenured generation

   AdaptiveSizeStart: 0.327 collection: 2
   -- Adaptive Size Policy started

   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: 18628936
   -- Suggested to increase "eden" to 419430400 based on space analysis

   PSAdaptiveSizePolicy::compute_eden_space_size:
      costs minor_time: 0.132738 major_cost: 0.000000
      mutator_cost: 0.867262 throughput_goal: 0.990000
      live_space: 287064392 free_space: 419430400
      old_eden_size: 209715200 desired_eden_size: 209715200
   -- Suggested to keep "eden" as 209715200 based on GC time cost

   AdaptiveSizeStop: collection: 2
   -- Adaptive Size Policy started