Maximum Logging of All Phases on Old GC

Java GC Tutorials - Herong's Tutorial Examples

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

∟Maximum Logging of All Phases on Old GC

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

If you want to know how many phases are performed in a CMS Old 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 Old 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 "GC\(\d+\) Old: \d+K" pattern:

[info ][gc,heap] GC(8) Old: 45802K->31461K(61440K)

This log message indicates that the CMS collector ended a complete Old GC (GC #8).

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

GC(8) Pause Initial Mark
GC(8) checkpointRootsInitialWork
GC(8) eden 0x00000000fb000000-0x00000000fb159f48-...
GC(8) _eden_chunk_index=2, _eden_chunk_capacity=1217
GC(8) _eden_chunk_array[0]=0x00000000fb100010
GC(8) _eden_chunk_array[1]=0x00000000fb159f48
GC(8) survivor 0x00000000fc300000-0x00000000fc300000-...
GC(8) _survivor_chunk_index=0, _survivor_chunk_capacity=512
GC(8) oops_do_marking_prologue
GC(8) WorkerManager::add_workers() : created_workers: 2
GC(8) GC Thread: using 2 out of 8 workers
GC(8) Finished young gen initial mark scan work in 0th thread: 0s
GC(8) Finished young gen initial mark scan work in 1th thread: 0s
GC(8) Finished remaining root initial mark scan work in 0th thread: 0s
GC(8) Finished remaining root initial mark scan work in 1th thread: 0s
GC(8) WorkerManager::add_workers() : created_workers: 2
GC(8) GC Thread: using 2 out of 8 workers
GC(8) oops_do_marking_epilogue
GC(8) checkpointRootsInitialWork 0.313ms
GC(8) Pause Initial Mark 46M->46M(79M) 0.332ms
GC(8) User=0.00s Sys=0.00s Real=0.00s
   -- Initial Mark, Pause, 0.332ms, 2 threads

GC(8) Concurrent Mark
GC(8) WorkerPolicy::calc_default_active_workers() : active_workers(): 2
GC(8) WorkerManager::add_workers() : created_workers: 2
GC(8) CMS Thread: using 2 out of 2 workers
GC(8) Using 2 workers of 2 for marking
GC(8) Finished cms space scanning in 1th thread: 0.000 sec
GC(8) Finished cms space scanning in 0th thread: 0.001 sec
GC(8) Finished work stealing in 0th thread: 0.000 sec
GC(8) Finished work stealing in 1th thread: 0.001 sec
GC(8) Concurrent active time: 0.002ms
GC(8)  (CMS Concurrent Mark yielded 0 times)
GC(8) Concurrent Mark 1.569ms
GC(8) User=0.00s Sys=0.00s Real=0.00s
   -- Mark, Concurrent, 1.332ms, 2 threads

GC(8) Concurrent Preclean
GC(8) Preclean SoftReferences
GC(8) SoftRef before: 0 0 0 0 0 0 0 0 (0)
GC(8) SoftRef after: 0 0 0 0 0 0 0 0 (0)
GC(8) Preclean SoftReferences 0.039ms
GC(8) Preclean WeakReferences
GC(8) WeakRef before: 0 10 0 0 0 0 0 0 (10)
GC(8) WeakRef after: 0 0 0 0 0 0 0 0 (0)
GC(8) Preclean WeakReferences 0.023ms
GC(8) Preclean FinalReferences
GC(8) FinalRef before: 0 0 0 0 0 0 0 0 (0)
GC(8) FinalRef after: 0 0 0 0 0 0 0 0 (0)
GC(8) Preclean FinalReferences 0.021ms
GC(8) Preclean PhantomReferences
GC(8) PhantomRef before: 0 0 0 0 0 0 0 0 (0)
GC(8) PhantomRef after: 0 0 0 0 0 0 0 0 (0)
GC(8) Preclean PhantomReferences 0.047ms
GC(8)  (modUnionTable: 0 cards)
GC(8)  (cardTable: 11 cards, re-scanned 11 cards, 1 iterations)
GC(8) Concurrent active time: 0.000ms
GC(8)  (CMS Concurrent Preclean yielded 0 times)
GC(8) Concurrent Preclean 0.346ms
GC(8) User=0.00s Sys=0.00s Real=0.00s
   -- Preclean, Concurrent, 0.346ms, ? threads

GC(8) Concurrent Abortable Preclean
GC(8)  [0 iterations, 0 waits, 0 cards)]
GC(8) Concurrent active time: 0.000ms
GC(8)  (CMS Concurrent Abortable Preclean yielded 0 times)
GC(8) Concurrent Abortable Preclean 0.042ms
GC(8) User=0.00s Sys=0.00s Real=0.00s
   -- Abortable Preclean, Concurrent, 0.042ms, 2 threads

GC(8) Pause Remark
GC(8) YG occupancy: 17768 K (19456 K)
GC(8) checkpointRootsFinalWork
GC(8) eden 0x00000000fb000000-0x00000000fc15a048-...
GC(8) _eden_chunk_index=18, _eden_chunk_capacity=1217
GC(8) _eden_chunk_array[0]=0x00000000fb100010
GC(8) _eden_chunk_array[1]=0x00000000fb159f48
...
GC(8) _eden_chunk_array[17]=0x00000000fc15a048
GC(8) survivor 0x00000000fc300000-0x00000000fc300000-...
GC(8) _survivor_chunk_index=0, _survivor_chunk_capacity=512
GC(8) Rescan (parallel)
GC(8) oops_do_marking_prologue
GC(8) WorkerManager::add_workers() : created_workers: 2
GC(8) GC Thread: using 2 out of 8 workers
GC(8) Finished young gen rescan work in 0th thread: 0.000 sec
GC(8) Finished young gen rescan work in 1th thread: 0.000 sec
GC(8) Finished remaining root rescan work in 0th thread: 0.000 sec
GC(8) Finished remaining root rescan work in 1th thread: 0.000 sec
GC(8) Finished unhandled CLD scanning work in 0th thread: 0.000 sec
GC(8) Finished dirty CLD scanning work in 0th thread: 0.000 sec
GC(8) Finished dirty card rescan work in 1th thread: 0.000 sec
GC(8) Finished dirty card rescan work in 0th thread: 0.000 sec
GC(8) Finished work stealing in 0th thread: 0.000 sec
GC(8) Finished work stealing in 1th thread: 0.000 sec
GC(8) WorkerManager::add_workers() : created_workers: 2
GC(8) GC Thread: using 2 out of 8 workers
GC(8) oops_do_marking_epilogue
GC(8) Rescan (parallel) 0.328ms
GC(8) refProcessingWork
GC(8) Reference Processing
GC(8) Skipped phase1 of Reference Processing due to unavailable references
GC(8) Skipped phase2 of Reference Processing due to unavailable references
GC(8) Skipped phase3 of Reference Processing due to unavailable references
GC(8) Skipped phase4 of Reference Processing due to unavailable references
GC(8) Reference Processing: 0.0ms
GC(8)   Reconsider SoftReferences: 0.0ms
GC(8)   Notify Soft/WeakReferences: 0.0ms
GC(8)   Notify and keep alive finalizable: 0.0ms
GC(8)   Notify PhantomReferences: 0.0ms
GC(8) Reference Processing 0.217ms
GC(8) Weak Processing
GC(8) Weak Processing 0.010ms
GC(8) Class Unloading
GC(8) ClassLoaderData
GC(8) ClassLoaderData 0.007ms
GC(8) ResolvedMethodTable
GC(8) ResolvedMethodTable 0.009ms
GC(8) Class Unloading 0.179ms
GC(8) Scrub Symbol Table
GC(8) Scrub Symbol Table 0.222ms
GC(8) Scrub String Table
GC(8) Scrub String Table 0.026ms
GC(8) refProcessingWork 0.701ms
GC(8) checkpointRootsFinalWork 1.219ms
GC(8) Pause Remark 62M->62M(79M) 1.244ms
GC(8) User=0.00s Sys=0.00s Real=0.00s
   -- Remark, Pause, 1.244ms, 2 threads

GC(8) Concurrent Sweep
GC(8) size[3] :
GC(8) demand: 1, old_rate: 45970.136719, current_rate: 73.209167, ...
GC(8) size[4] :
GC(8) demand: 0, old_rate: 35479.605469, current_rate: 0.000000, ...
...
GC(8) size[255] :
GC(8) demand: 0, old_rate: 0.000000, current_rate: 0.000000, ...
GC(8) size[256] :
GC(8) demand: 0, old_rate: 0.000000, current_rate: 0.000000, ...
GC(8) demand: 1, old_rate: 0.000000, current_rate: 73.209167, ...
GC(8) CMS: Large Block: 0x00000000ff0e0438; Proximity: ...
GC(8) CMS: Large block 0x00000000ff0df670
GC(8) Concurrent active time: 0.006ms
GC(8)  (CMS Concurrent Sweep yielded 1 times)
GC(8) Concurrent Sweep 6.384ms
GC(8) User=0.02s Sys=0.00s Real=0.01s
   -- Sweep, Concurrent, 6.384ms, ? threads

GC(8) Old: 45802K->31461K(61440K)
   -- GC #8 (Old GC) ended

Cool. Now we know a CMS Old GC has 6 phases using different concurrency models.

            Phases   Threads   Time      Concurrency

      Initial Mark         2   0.332ms   pause - stop-the-world
              Mark         2   1.332ms   concurrent to app/ParNew
          Preclean         1   0.346ms   concurrent to app/ParNew
Abortable Preclean	       2   0.042ms   concurrent to app/ParNew
            Remark         2   1.244ms   pause stop-the-world
             Sweep         1   6.384ms   concurrent to app/ParNew

If you are still using JVM 8 or older versions, you may see slightly different phases:

      Phases   Threads   Concurrency

Initial Mark         4   stop-the-world
        Mark         1   concurrent to app/ParNew
    Preclean         1   concurrent to app/ParNew
  Final Mark         4   stop-the-world
       Sweep         1   concurrent to app/ParNew
       Reset         1   concurrent to app/ParNew