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

Java GC Tutorials - Herong's Tutorial Examples

∟Parallel Collector - "+XX:+UseParallelGC"

∟"--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:

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.