Maximum Logging of All Phases on Young GC

This section demonstrates that the '-Xlog:gc*=trace' option can be used to print out maximum logging messages of all phases on a Young GC performed by the CMS collector.

If you want to know how many phases are performed in a CMS Young GC process and how each phase is performed, you need to turn on the maximum GC logging with the "-Xlog:gc*=trace" option.

Here is what I did to capture all log messages of a single Young GC performed by the CMS collector.

1. Run the following command to capture all log messages in a file:

herong> java -XX:+UseConcMarkSweepGC \
   -Xms1200m -Xmx1200m -XX:NewRatio=1 -XX:SurvivorRatio=1 \
   -Xlog:gc*=trace \
   GarbageCollection2 > output.txt

2. Open the log file, output.txt, in text editor. And find log message lines with this regular express "Pause Young \(Allocation Failure\)" pattern. Take one of them like:

[info][gc,start] GC(1) Pause Young (Allocation Failure)

This log message indicates that the CMS collector started a Young GC (GC #1).

3. Search all log message lines with "GC\(1\)" in the editor to get all log messages of GC #1:

GC(1) Heap before GC invocations=1 (full 0): par new generation   ...
GC(1)   eden space 204800K,  99% used [...
GC(1)   from space 204800K,  15% used [...
GC(1)   to   space 204800K,   0% used [...
GC(1)  concurrent mark-sweep generation total 614400K, used 0K [...]
GC(1)  Metaspace    used 556K, capacity 4546K, committed 4864K, ...
GC(1)   class space used 42K, capacity 408K, committed 512K, ...
   -- Heap report before GC

GC(1) Pause Young (Allocation Failure)
   -- GC #1 (Young GC) started because Young generation is full

GC(1) TLAB: gc thread: 0x02b498e27000 [id: 63172] desired_size: 4013KB...
GC(1) TLAB: gc thread: 0x02b498eea000 [id: 58376] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b498eef800 [id: 66440] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b3c7c800 [id: 58080] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b3c7e800 [id:  8292] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b3c80000 [id: 66164] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b3c84800 [id: 56344] desired_size: 2048KB...
GC(1) TLAB: gc thread: 0x02b4b3c97000 [id: 64444] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b4498800 [id: 26416] desired_size: 4096KB...
GC(1) TLAB: gc thread: 0x02b4b44b4800 [id: 65516] desired_size: 4096KB...
GC(1) TLAB totals: thrds: 2  refills: 2 max: 1 slow allocs: 194 max 194
waste: 48.8% gc: 3026712B max: 2097112B slow: 0B max: 0B fast: 0B max: 0B
   -- TLAB report before GC
GC(1) Collect gen: ParNew
   -- Collect gen: ParNew - started

GC(1) Young invoke=2 size=1048592
GC(1) WorkerPolicy::calc_default_active_workers() : active_workers(): 8
new_active_workers: 8  prev_active_workers: 8
GC(1) WorkerManager::add_workers() : created_workers: 8
GC(1) GC Thread: using 8 out of 8 workers
GC(1) Using 8 workers of 8 for evacuation
   -- 8 threads used

GC(1) ParNew (Allocation Failure)
   -- ParNew started

GC(1) oops_do_marking_prologue
GC(1) WorkerManager::add_workers() : created_workers: 8
GC(1) GC Thread: using 8 out of 8 workers
GC(1)  317  3  GarbageCollection2::getOneMega (5 bytes)   oops_do, mark
GC(1)  317  3  GarbageCollection2::getOneMega (5 bytes)   scavenge root
GC(1)  315  3  java.util.Random::nextInt (74 bytes)   scavenge root
GC(1)  315  3  java.util.Random::nextInt (74 bytes)   oops_do, mark
GC(1)  314  3  java.lang.System::lineSeparator (4 bytes)   scavenge root
GC(1)  314  3  java.lang.System::lineSeparator (4 bytes)   oops_do, mark
...
   -- oops_do_marking_prologue ended
   -- "oops_do, mark" and "scavenge root" on each object type

GC(1) WorkerManager::add_workers() : created_workers: 8
GC(1) GC Thread: using 8 out of 8 workers
GC(1) oops_do_marking_epilogue
GC(1) Skipped phase1 of Reference Processing due to unavailable references
GC(1) Phase2 Soft before0 0 0 0 0 0 0 0 (0)
GC(1) Phase2 Weak before0 88 0 5 0 0 1 0 (94)
GC(1) Phase2 Final before0 0 0 0 0 0 0 0 (0)
GC(1) Phase2 Final after0 0 0 0 0 0 0 0 (0)
GC(1) Skipped phase3 of Reference Processing due to unavailable references
GC(1) Phase4 Phantom before0 0 0 0 0 0 1 0 (1)
GC(1) Reference Processing: 0.1ms
GC(1)   Reconsider SoftReferences: 0.0ms
GC(1)     SoftRef: skipped
GC(1)   Notify Soft/WeakReferences: 0.0ms
GC(1)     SoftRef: 0.0ms
GC(1)     WeakRef: 0.0ms
GC(1)     FinalRef: 0.0ms
GC(1)     Total: 0.0ms
GC(1)   Notify and keep alive finalizable: 0.0ms
GC(1)     FinalRef: skipped
GC(1)   Notify PhantomReferences: 0.0ms
GC(1)     PhantomRef: 0.0ms
GC(1)   SoftReference:
GC(1)     Discovered: 0
GC(1)     Cleared: 0
GC(1)   WeakReference:
GC(1)     Discovered: 94
GC(1)     Cleared: 94
GC(1)   FinalReference:
GC(1)     Discovered: 0
GC(1)     Cleared: 0
GC(1)   PhantomReference:
GC(1)     Discovered: 1
GC(1)     Cleared: 1
   -- oops_do_marking_epilogue ended
GC(1) Desired survivor size 104857600 bytes, new threshold 15
       (max threshold 15)
GC(1) Age table with threshold 15 (max threshold 15)
GC(1) - age   1:   31457760 bytes,   31457760 total
GC(1) - age   2:    1800712 bytes,   33258472 total
   -- Aging report

GC(1) Young PLAB allocation: allocated: 983232B, wasted: 568B, ...
GC(1) Young sizing: calculated: 752032B, actual: 727896B
GC(1) ParNew (Allocation Failure) 20.173ms
   -- ParNew ended

GC(1) Collect gen: ParNew 20.282ms
   -- Collect gen: ParNew - ended

GC(1) ParNew: 237219K->32704K(409600K)
GC(1) CMS: 0K->0K(614400K)
GC(1) Metaspace: 556K->556K(1056768K)
   -- ParNew GC report

GC(1) TLAB new size: thread: 0x000002b498e27000 [id: 63172] refills 50...
GC(1) TLAB new size: thread: 0x000002b498eea000 [id: 58376] refills 50...
GC(1) TLAB new size: thread: 0x000002b498eef800 [id: 66440] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b3c7c800 [id: 58080] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b3c7e800 [id:  8292] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b3c80000 [id: 66164] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b3c84800 [id: 56344] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b3c97000 [id: 64444] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b4498800 [id: 26416] refills 50...
GC(1) TLAB new size: thread: 0x000002b4b44b4800 [id: 65516] refills 50...
   -- TLAB report after GC

GC(1) Pause Young (Allocation Failure) 231M->31M(1000M) 21.052ms
GC(1) User=0.02s Sys=0.02s Real=0.02s
   -- Young GC report

GC(1) Heap after GC invocations=2 (full 0): par new generation
       total 409600K, used 32704K [...
GC(1)   eden space 204800K,   0% used [...
GC(1)   from space 204800K,  15% used [...
GC(1)   to   space 204800K,   0% used [...
GC(1)  concurrent mark-sweep generation total 614400K, used 0K [...
   -- Heap report after GC

As you can see from log messages, a Young GC is performed with 2 primary phases.

                  Phases  Threads  Time     Concurrency

oops_do_marking_prologue  8        ?.???ms  pause - stop-the-world
oops_do_marking_epilogue  8        ?.???ms  pause - stop-the-world

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"

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

 What Is Concurrent Mark-Sweep (CMS) Collector

 Concurrent Mark-Sweep Collector GC Log Message Format

 Reduce Stop-The-World with Concurrent Mark and Sweep

 Parallel New (ParNew) Collector for Minor GC

 ParNew Collector - Tenuring Age Distribution

Maximum Logging of All Phases on Young GC

 "-XX:ParallelGCThreads=6" - Young GC Parallel Threads

 "-XX:MaxTenuringThreshold=0" - Tenuring Objects Immediately

 "-XX:CMSInitiatingOccupancyFraction=20" - Initiate CMS

 Maximum Logging of All Phases on Old GC

 Maximum Logging of All Phases on Full GC

 "-XX:ParallelGCThreads=6" - Old GC Parallel Threads

 "-XX:ConcGCThreads=3" - Old GC Concurrent Threads

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

 The Z Garbage Collector (ZGC) - "+XX:+UseZGC"

 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

 References

 Full Version in PDF/EPUB