"--Xlog:gc+task+time=debug" - Print GC Threads

This section describes how to use the '-Xlog:gc+task+time=debug' JVM option to show multiple GC threads used by the Parallel Collector.

One key characteristic of the Parallel collector is that it uses multiple parallel threads to perform garbage collection processes.

Let's use the "-Xlog:gc+task+time=debug" JVM option to confirm this behavior:

C:\herong>java -Xms40m -Xmx80m -XX:+UseParallelGC
   -Xlog:gc=debug,gc+heap=info,gc+task+time=debug GarbageCollection

[info][gc] Using Parallel
[info][gc,heap] GC(0) PSYoungGen: 10240K->1504K(11776K)
[info][gc,heap] GC(0) ParOldGen: 0K->1856K(27648K)
[info][gc] GC(0) Pause Young (Allocation Failure) 10M->3M(38M) 5.849ms

[debug][gc,task,time] GC(0) VM-Thread 809930 820635 821485
[debug][gc,task,time] GC(0) GC-Thread 0 entries: 5
[debug][gc,task,time] GC(0)     [ noop task 811238 811239 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 811259 811316 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 811317 811324 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811324 819815 ]
[debug][gc,task,time] GC(0)     [ steal-task 819816 820569 ]
[debug][gc,task,time] GC(0) GC-Thread 1 entries: 19
[debug][gc,task,time] GC(0)     [ thread-roots-task 811479 811576 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811577 811673 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811673 811675 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811675 811677 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811677 811678 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811678 811679 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811679 811681 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811681 811756 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811756 811761 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811762 811764 ]
[debug][gc,task,time] GC(0)     [ thread-roots-task 811765 811766 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 811766 811767 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 811767 811770 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 811770 815786 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 815787 819042 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 819043 819053 ]
[debug][gc,task,time] GC(0)     [ scavenge-roots-task 819053 819728 ]
[debug][gc,task,time] GC(0)     [ steal-task 819729 820556 ]
[debug][gc,task,time] GC(0)     [ waitfor-barrier-task 820557 820594 ]

From the output, I can see that the Parallel Collector did use 2 threads to perform the first Minor GC. But I am not sure if those multiple threads were actually executed parallely on multiple CPUs.

Continue to GC(3):

[debug][gc     ] GC(3) Expanding ParOldGen from 27648K by 27136K to 54784K
[info ][gc,heap] GC(3) PSYoungGen: 1520K->0K(25600K)
[info ][gc,heap] GC(3) ParOldGen: 25676K->25000K(54784K)
[info ][gc     ] GC(3) Pause Full (Ergonomics) 26M->24M(78M) 21.810ms

[debug][gc,task,time] GC(3) VM-Thread 239564030 239584139 239606425
[debug][gc,task,time] GC(3) GC-Thread 0 entries: 6
[debug][gc,task,time] GC(3)   [ noop task 239564056 239564063 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239564487 239567537 ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239567538 ... ]
[debug][gc,task,time] GC(3)   [ steal-marking-task 239577220 239577223 ]
[debug][gc,task,time] GC(3)   [ waitfor-barrier-task 239577223 239577243 ]
[debug][gc,task,time] GC(3)   [ steal-region-task 239584193 239604309 ]
[debug][gc,task,time] GC(3) GC-Thread 1 entries: 22
[debug][gc,task,time] GC(3)   [ noop task 239564016 239564018 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239564512 239575623 ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575625 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575642 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575650 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575651 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575651 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575655 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575656 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575657 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575664 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575667 ... ]
[debug][gc,task,time] GC(3)   [ thread-roots-marking-task 239575668 ... ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575669 239575670 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575670 239575672 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575672 239575681 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575681 239575698 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575699 239575699 ]
[debug][gc,task,time] GC(3)   [ mark-from-roots-task 239575699 239575700 ]
[debug][gc,task,time] GC(3)   [ steal-marking-task 239575700 239577231 ]
[debug][gc,task,time] GC(3)   [ steal-region-task 239584202 239604309 ]
[debug][gc,task,time] GC(3)   [ waitfor-barrier-task 239604316 239604350 ]

The output also shows that the Parallel Collector did use 2 multiple threads to perform the first Full GC. But I am not sure if those multiple threads were actually executed parallely on multiple CPUs.

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

 Log Message Types from Parallel Collector

"--Xlog:gc+task+time=debug" - Print GC Threads

 "-XX:ParallelGCThreads" - # 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

 "-Xlog:gc+ergo=trace" - Minor GC Report

 Adaptive Size Policy Changed Survivor Space

 Adaptive Size Policy Changed Eden Space

 Adaptive Size Policy for Best Latency

 Parallel Collector Stopped using Young Generation

 Adaptive Size Policy for Best Throughput

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

 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