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:

C:\>\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                                {product}

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

Last update: 2018.

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

 "-XX:+PrintGCTaskTimeStamps" - Print GC Threads

 "-XX:ParallelGCThreads=n" - # 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

 "-XX:+PrintAdaptiveSizePolicy" - Minor GC Report

 Adaptive Size Policy Changed Survivor Space

 Adaptive Size Policy Changed Eden Space

 Adaptive Size Policy for Best Latency

 Adaptive Size Policy for Best Throughput

 Concurrent Mark-Sweep (CMS) Collector - "+XX:+UseConcMarkSweepGC"

 Garbage First (G1) Collector - "+XX:+UseG1GC"

 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

 Outdated Tutorials

 References

 Full Version in PDF/EPUB