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

herong> \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

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

 Archived Tutorials

 References

 Full Version in PDF/EPUB