Maximum Logging of All Phases on Young GC

Java GC Tutorials - Herong's Tutorial Examples

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

∟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