Java GC Tutorials - Herong's Tutorial Examples - Version 1.01, by Dr. Herong Yang
"-XX:+PrintAdaptiveSizePolicy" - Minor GC Report
This section provides examples of log messages generated from '-XX:+PrintAdaptiveSizePolicy' that tells us what happened at each Parallel Minor GC.
One piece of information in the log messages generated from the "-XX:+PrintAdaptiveSizePolicy" JVM option, tells us the amount of data survived in Young generation and the amount of data promoted to Tenured generation for each Minor GC:
[GC (Allocation Failure) AdaptiveSizePolicy::update_averages: survived: 17064240 promoted: 5247056 overflow: false
This information is useful if you want to know what exactly happened at each Minor GC.
For example, if we run GarbageCollection2.java with the following JVM options, we can get enough log messages to figure what happened at each Minor GC:
C:\>\progra~1\java\jdk1.8.0\bin\java -XX:+UseParallelGC -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintAdaptiveSizePolicy -Xms400m -Xmx400m GarbageCollection2
Here is what happened at GC #1:
97 402128896 297259104 104869792 Application time: 0.1588408 seconds {Heap before GC invocations=1 (full 0): PSYoungGen total 119552K, used 102411K [... eden space 102656K, 99% used [0x150c0000,0x1b4c2fa0,0x1b500000) from space 16896K, 0% used [0x1c580000,0x1c580000,0x1d600000) to space 16896K, 0% used [0x1b500000,0x1b500000,0x1c580000) ParOldGen total 273152K, used 0K [... object space 273152K, 0% used [0x04600000,0x04600000,0x150c0000) [GC (Allocation Failure) AdaptiveSizePolicy::update_averages: survived: 17064240 promoted: 5247056 overflow: false -- 17064240 bytes survived in "from" space -- 5247056 bytes promoted to Tenured generation -- Bytes removed: 102411K - 17064240 - 5247056 = 82557568 bytes -- Bytes in Tenured generation: 0 + 5247056 = 5247056 bytes AdaptiveSizeStart: 0.263 collection: 1 ... [PSYoungGen: 102411K->16664K(119552K)] 102411K->21788K(392704K), 0.0121477 secs] Heap after GC invocations=1 (full 0): PSYoungGen total 119552K, used 16664K [... eden space 102656K, 0% used [0x150c0000,0x150c0000,0x1b500000) from space 16896K, 98% used [0x1b500000,0x1c546130,0x1c580000) to space 16896K, 0% used [0x1c580000,0x1c580000,0x1d600000) ParOldGen total 273152K, used 5124K [... object space 273152K, 1% used [0x04600000,0x04b01050,0x150c0000) -- 5124K in Tenured generation, matching above calculation } Total time for which application threads were stopped: 0.0126340 s 98 402128896 378769008 23359888
Here is what happened at GC #2:
196 402128896 274995280 127133616 Application time: 0.0131630 seconds {Heap before GC invocations=2 (full 0): PSYoungGen total 119552K, used 119029K [... eden space 102656K, 99% used [0x150c0000,0x1b4b7630,0x1b500000) from space 16896K, 98% used [0x1b500000,0x1c546130,0x1c580000) to space 16896K, 0% used [0x1c580000,0x1c580000,0x1d600000) ParOldGen total 273152K, used 5124K [... object space 273152K, 1% used [0x04600000,0x04b01050,0x150c0000) [GC (Allocation Failure) AdaptiveSizePolicy::update_averages: survived: 17039680 promoted: 1048592 overflow: false -- 17064240 bytes survived in "from" space -- 1048592 bytes promoted to Tenured generation -- Bytes removed: 102411K - 1048592 = 103820272 bytes -- Bytes in Tenured generation: 5247056 + 1048592 = 6295648 bytes AdaptiveSizeStart: 0.285 collection: 2 ... [PSYoungGen: 119029K->16640K(119552K)] 124153K->22788K(392704K), 0.0085299 secs] Heap after GC invocations=2 (full 0): PSYoungGen total 119552K, used 16640K [... eden space 102656K, 0% used [0x150c0000,0x150c0000,0x1b500000) from space 16896K, 98% used [0x1c580000,0x1d5c0140,0x1d600000) to space 16896K, 0% used [0x1b500000,0x1b500000,0x1c580000) ParOldGen total 273152K, used 6148K [... object space 273152K, 2% used [0x04600000,0x04c01060,0x150c0000) -- 6148K in Tenured generation, matching above calculation } Total time for which application threads were stopped: 0.0089765 seconds, 197 402128896 377744976 24383920
Here is what happened at GC #82 and #83, a minor and major GC combination:
8095 401866752 10480520 391386232 Application time: 0.0195224 seconds {Heap before GC invocations=82 (full 0): PSYoungGen total 119296K, used 117737K [... eden space 102144K, 99% used [0x150c0000,0x1b3ba4e8,0x1b480000) from space 17152K, 95% used [0x1b480000,0x1c480100,0x1c540000) to space 17152K, 0% used [0x1c540000,0x1c540000,0x1d600000) ParOldGen total 273152K, used 264475K [... object space 273152K, 96% used [0x04600000,0x14846e90,0x150c0000) [GC (Allocation Failure) AdaptiveSizePolicy::update_averages: survived: 16777472 promoted: 2097184 overflow: false AdaptiveSizeStart: 2.327 collection: 82 ... [PSYoungGen: 117737K->16384K(119552K)] 382213K->282907K(392704K), 0.0068961 secs] Heap after GC invocations=82 (full 0): PSYoungGen total 119552K, used 16384K [... eden space 102400K, 0% used [0x150c0000,0x150c0000,0x1b4c0000) from space 17152K, 95% used [0x1c540000,0x1d540100,0x1d600000) to space 16896K, 0% used [0x1b4c0000,0x1b4c0000,0x1c540000) ParOldGen total 273152K, used 266523K [... object space 273152K, 97% used [0x04600000,0x14a46eb0,0x150c0000) } -- Tenured generation was 97%, too full to run application -- Major GC (Full GC) triggered {Heap before GC invocations=83 (full 1): PSYoungGen total 119552K, used 16384K [... eden space 102400K, 0% used [0x150c0000,0x150c0000,0x1b4c0000) from space 17152K, 95% used [0x1c540000,0x1d540100,0x1d600000) to space 16896K, 0% used [0x1b4c0000,0x1b4c0000,0x1c540000) ParOldGen total 273152K, used 266523K [... object space 273152K, 97% used [0x04600000,0x14a46eb0,0x150c0000) [Full GC (Ergonomics) AdaptiveSizeStart: 2.400 collection: 83 ... [PSYoungGen: 16384K->0K(119552K)] [ParOldGen: 266523K->18678K(273152K)] 282907K->18678K(392704K), Heap after GC invocations=83 (full 1): PSYoungGen total 119552K, used 0K [... eden space 102400K, 0% used [0x150c0000,0x150c0000,0x1b4c0000) from space 17152K, 0% used [0x1c540000,0x1c540000,0x1d600000) to space 16896K, 0% used [0x1b4c0000,0x1b4c0000,0x1c540000) ParOldGen total 273152K, used 18678K [... object space 273152K, 6% used [0x04600000,0x0583d8f0,0x150c0000) -- 6148K in Tenured generation -- 0K in Young generation } Total time for which application threads were stopped: 0.0795678 seconds, 8096 402128896 381953792 20175104
Last update: 2018.
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