Maximum Logging of All Phases on Full GC

Java GC Tutorials - Herong's Tutorial Examples

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

∟Maximum Logging of All Phases on Full GC

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

If you want to know how many phases are performed in a CMS Full 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 Full GC performed by the CMS collector.

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

herong> java -XX:+UseConcMarkSweepGC \
   -Xms80m -Xmx80m -XX:NewRatio=3 -XX:SurvivorRatio=18 \
   -XX:MaxTenuringThreshold=0 \
   -XX:CMSInitiatingOccupancyFraction=20 \
   -XX:+UseCMSInitiatingOccupancyOnly \
   -Xlog:gc*=trace \
   GarbageCollection2 > output.txt

2. Open the log file, output.txt, in text editor. And find the first log message line with this regular express "Pause Full \(Allocation Failure\)" pattern:

[info][gc,start] GC(6) Pause Full (Allocation Failure)

This log message indicates that the CMS collector started a Full GC (GC #6).

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

GC(6) Pause Full (Allocation Failure)
GC(6) Collect gen: CMS
GC(6) Old invoke=1 size=1048592
GC(6) Concurrent mode failure
   -- GC #6 (Full GC) started because heap is full

GC(6)  num     #instances         #bytes  class name (module)
GC(6) -------------------------------------------------------
GC(6)    1:            74       72353952  [J (java.base@12.0.1)
GC(6)    2:           276         567640  [I (java.base@12.0.1)
GC(6)    3:          2631         130560  [B (java.base@12.0.1)
GC(6)    4:          1284          82024  [Ljava.lang.Object; (...)
GC(6)    5:           703          80760  java.lang.Class (...)
GC(6)    6:          2541          60984  java.lang.String (...)
GC(6)    7:          1640          52480  java.util.HashMap$Node (...)
GC(6)    8:            16          42448  [C (java.base@12.0.1)
...
GC(6) Total         16689       73670144
GC(6) Class Histogram (before full gc) 3.344ms
   -- Class Histogram Before GC, 3.344ms

GC(6) CMS:MSC
   -- MSC (Mark Sweep Compact) process started

GC(6) size[3] :
GC(6) demand: 6595, old_rate: 0.000000, current_rate: 45970.136719, ...
GC(6) size[4] :
GC(6) demand: 5090, old_rate: 0.000000, current_rate: 35479.605469, ...
GC(6) size[5] :
GC(6) demand: 1227, old_rate: 0.000000, current_rate: 8552.746094, ...
...
GC(6) size[256] :
GC(6) demand: 0, old_rate: 0.000000, current_rate: 0.000000, ...
GC(6) demand: 1, old_rate: 0.000000, current_rate: 6.970453, ...
   -- Some kind of sweeping phase, ? ms

GC(6) Phase 1: Mark live objects
GC(6) oops_do_marking_prologue
GC(6) oops_do_marking_epilogue
GC(6) Reference Processing
GC(6) Skipped phase1 of Reference Processing due to unavailable references
GC(6) Phase2 Soft before0 0 0 0 0 0 0 0 (0)
GC(6) Phase2 Weak before56 0 0 0 0 0 0 0 (56)
GC(6) Phase2 Final before0 0 0 0 0 0 0 0 (0)
GC(6) Phase2 Final after0 0 0 0 0 0 0 0 (0)
GC(6) Skipped phase3 of Reference Processing due to unavailable references
GC(6) Phase4 Phantom before1 0 0 0 0 0 0 0 (1)
GC(6) Reference Processing: 0.1ms
GC(6)   Reconsider SoftReferences: 0.0ms
GC(6)     SoftRef: skipped
GC(6)   Notify Soft/WeakReferences: 0.0ms
GC(6)     SoftRef: 0.0ms
GC(6)     WeakRef: 0.0ms
GC(6)     FinalRef: 0.0ms
GC(6)     Total: 0.0ms
GC(6)   Notify and keep alive finalizable: 0.0ms
GC(6)     FinalRef: skipped
GC(6)   Notify PhantomReferences: 0.0ms
GC(6)     PhantomRef: 0.0ms
GC(6)   SoftReference:
GC(6)     Discovered: 0
GC(6)     Cleared: 0
GC(6)   WeakReference:
GC(6)     Discovered: 56
GC(6)     Cleared: 12
GC(6)   FinalReference:
GC(6)     Discovered: 0
GC(6)     Cleared: 0
GC(6)   PhantomReference:
GC(6)     Discovered: 1
GC(6)     Cleared: 0
GC(6) Reference Processing 0.228ms
GC(6) Weak Processing
GC(6) Weak Processing 0.011ms
GC(6) Class Unloading
GC(6) ClassLoaderData
GC(6) ClassLoaderData 0.007ms
GC(6) ResolvedMethodTable
GC(6) ResolvedMethodTable 0.008ms
GC(6) Class Unloading 0.163ms
GC(6) Scrub String Table
GC(6) Scrub String Table 0.285ms
GC(6) Scrub Symbol Table
GC(6) Scrub Symbol Table 0.240ms
GC(6) Phase 1: Mark live objects 2.004ms
   -- "Mark live objects" phase ended, 2.004ms

GC(6) Phase 2: Compute new object addresses
GC(6) Phase 2: Compute new object addresses 0.339ms
   -- "Compute new object addresses" phase ended, 0.339ms

GC(6) Phase 3: Adjust pointers
GC(6) oops_do_marking_prologue
GC(6)   20       1       java.lang.Object::<init> (1 bytes)   ...
GC(6)   22       1       java.lang.module.ModuleDescriptor::name ...
GC(6)   25       1       java.lang.module.ModuleReference::descriptor...
GC(6)   15       4       java.lang.StringLatin1::hashCode (42 bytes) ...
GC(6)   29       1       java.util.KeyValueHolder::getKey (5 bytes) ...
GC(6)   30       1       java.util.KeyValueHolder::getValue (5 bytes)...
...
GC(6) oops_do_marking_epilogue
GC(6) Phase 3: Adjust pointers 5.032ms
   -- "Adjust pointers" phase ended, 5.032ms

GC(6) Phase 4: Move objects
GC(6) Phase 4: Move objects 5.850ms
   -- "Move objects" phase ended, 5.850ms

GC(6) Restoring 7827 marks
GC(6) CMS: Large block 0x00000000fe2d97b8
GC(6)  num     #instances         #bytes  class name (module)
GC(6) -------------------------------------------------------
GC(6)    1:            35       31458864  [J (java.base@12.0.1)
GC(6)    2:          2605         129016  [B (java.base@12.0.1)
GC(6)    3:          1284          82024  [Ljava.lang.Object; (...)
GC(6)    4:           703          80760  java.lang.Class (...)
GC(6)    5:          2515          60360  java.lang.String (...)
GC(6)    6:          1640          52480  java.util.HashMap$Node (...)
GC(6)    7:            16          42448  [C (java.base@12.0.1)
...
GC(6) Total         16433       32209224
GC(6) Class Histogram (after full gc) 2.451ms
   -- "Class Histogram After GC" phase ended, 2.451ms

GC(6) CMS:MSC 21.854ms
   -- MSC (Mark Sweep Compact) process ended

GC(6) PSAdaptiveSizePolicy::check_gc_overhead_limit: promo_limit: ...
GC(6) Collect gen: CMS 25.447ms

GC(6) Pause Full (Allocation Failure) 70M->30M(79M) 25.469ms
   -- GC #6 (Full GC) ended

As you can see from log messages, a Full GC is performed with the following phases.

                      Phases  Threads  Time     Concurrency

   Class Histogram Before GC        1  3.344ms  pause - stop-the-world
       Some kind of sweeping        1  ?.???ms  pause - stop-the-world
           Mark live objects        1  2.004ms  pause - stop-the-world
Compute new object addresses        1  0.339ms  pause - stop-the-world
             Adjust pointers        1  5.032ms  pause - stop-the-world
                Move objects        1  5.850ms  pause - stop-the-world
    Class Histogram After GC        1  2.451ms  pause - stop-the-world

Full GCs have major impacts on application performance. They take longer time than Old GC, and stop the application while performing them. You should optimize GC configurations to avoid Full GCs.