Java 8 GC Tutorials - Herong's Tutorial Examples - v1.03, by Dr. Herong Yang
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
Table of Contents
Heap Memory Area and Size Control
JVM Garbage Collection Logging
Introduction of Garbage Collectors
Serial Collector - "+XX:+UseSerialGC"
►Parallel Collector - "+XX:+UseParallelGC"
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