Log Message Types from Parallel Collector

This section describes various types of log messages generated from the Parallel Collector with the '-Xlog:gc*=debug' option.

If you run your application using the Serial Collector (-XX:+UseParallelGC) with the "-Xlog:gc*=debug" logging option, you may see the following types of log messages:

1. Heap initial allocation - Reported when JVM starts:

[debug][gc,heap] Minimum heap 41943040  Initial heap 41943040
   Maximum heap 83886080

2. Young generation heap reduction message - Reported as part of a Young GC process:

[info][gc,heap] GC(0) PSYoungGen: 10240K->1504K(11776K)

3. Tenured generation heap expansion message - Reported as part of a Young GC process:

[0.352s][info][gc,heap] GC(0) ParOldGen: 0K->1856K(27648K)

4. Start/end of a Young GC:

[info][gc,start] GC(0) Pause Young (Allocation Failure)
...
[info][gc] GC(0) Pause Young (Allocation Failure) 10M->3M(38M) 6.940ms

5. Object aging threshold - Reported as part of a Young GC:

[debug][gc,age] GC(0) Desired survivor size 65536 bytes,
                      new threshold 1 (max threshold 15)
[debug][gc,age] GC(0) Desired survivor size 1572864 bytes,
                      new threshold 7 (max threshold 15)

6. Metaspace reduction - Reported as part of a Young GC:

[info ][gc,metaspace] GC(0) Metaspace: 7584K->7584K(1058816K)

7. GC execution time - Reported as part of a Young or Full GC:

[info][gc,cpu] GC(0) User=0.00s Sys=0.00s Real=0.00s

8. Heap snapshot report before GC - Reported before a Young GC or Full GC process:

[debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0):
                        def new generation total 1152K, used 1024K ...
[debug][gc,heap] GC(0)   eden space 1024K, 100% used [...
[debug][gc,heap] GC(0)   from space 128K,   0% used [...
[debug][gc,heap] GC(0)   to   space 128K,   0% used [...
[debug][gc,heap] GC(0)  tenured generation   total 768K, used 0K [...
[debug][gc,heap] GC(0)    the space 768K,   0% used [...
[debug][gc,heap] GC(0)  Metaspace
                          used 328K, capacity 4515K, committed 4864K,
						  reserved 1056768K
[debug][gc,heap] GC(0)   class space
                          used 30K, capacity 398K, committed 512K,
						  reserved 1048576K

9. Heap snapshot report after GC - Reported before a Young GC or Full GC process:

[debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
                        def new generation total 1152K, used 128K [...
[debug][gc,heap] GC(0)   eden space 1024K,   0% used [...
[debug][gc,heap] GC(0)   from space 128K, 100% used [...
[debug][gc,heap] GC(0)   to   space 128K,   0% used [...
[debug][gc,heap] GC(0)  tenured generation   total 768K, used 418K [...
[debug][gc,heap] GC(0)    the space 768K,  54% used [...
[debug][gc,heap] GC(0)  Metaspace
                          used 328K, capacity 4515K, committed 4864K,
						  reserved 1056768K
[debug][gc,heap] GC(0)   class space
                          used 30K, capacity 398K, committed 512K,
						  reserved 1048576K

10. Start/end of Scavenge phase of a Young GC:

[debug][gc,phases,start] GC(0) Scavenge
...
[debug][gc,phases      ] GC(0) Scavenge 5.753ms

11. Start/end of Reference Processing phase of a Young GC:

[debug][gc,phases,start] GC(0) Reference Processing
...
[debug][gc,phases      ] GC(0) Reference Processing 0.249ms

12. Start/end of Weak Processing phase of a Young GC:

[debug][gc,phases,start] GC(0) Weak Processing
...
[debug][gc,phases      ] GC(0) Weak Processing 0.028ms

13. Start/end of Scrub String Table phase of a Young GC:

[debug][gc,phases,start] GC(0) Scrub String Table
[debug][gc,phases      ] GC(0) Scrub String Table 0.117ms

14. Thread report of a Youg GC:

[debug][gc,task,time   ] GC(1) VM-Thread 994681 1004762 1005959
[debug][gc,task,time   ] GC(1) GC-Thread 0 entries: 21
[debug][gc,task,time   ] GC(1) 	[ noop task 995002 995002 ]
[debug][gc,task,time   ] GC(1) 	[ old-to-young-roots-task 995034 1001885 ]
[debug][gc,task,time   ] GC(1) 	[ thread-roots-task 1001887 1001898 ]
...
[debug][gc,task,time   ] GC(1) 	[ thread-roots-task 1001932 1001933 ]
[debug][gc,task,time   ] GC(1) 	[ scavenge-roots-task 1001933 1001934 ]
...
[debug][gc,task,time   ] GC(1) 	[ scavenge-roots-task 1002736 1003819 ]
[debug][gc,task,time   ] GC(1) 	[ steal-task 1003820 1004604 ]
[debug][gc,task,time   ] GC(1) GC-Thread 1 entries: 7
[debug][gc,task,time   ] GC(1) 	[ noop task 995014 995019 ]
[debug][gc,task,time   ] GC(1) 	[ old-to-young-roots-task 995041 1001604 ]
[debug][gc,task,time   ] GC(1) 	[ scavenge-roots-task 1001606 1001614 ]
[debug][gc,task,time   ] GC(1) 	[ scavenge-roots-task 1001614 1001618 ]
[debug][gc,task,time   ] GC(1) 	[ thread-roots-task 1001618 1004083 ]
[debug][gc,task,time   ] GC(1) 	[ steal-task 1004083 1004590 ]
[debug][gc,task,time   ] GC(1) 	[ waitfor-barrier-task 1004590 1004620 ]

15. Start/end of a Full GC - Reported at the beginning of a Full GC:

[info ][gc,start] GC(3) Pause Full (Ergonomics)
...
[info ][gc      ] GC(3) Pause Full (Ergonomics) 27M->24M(78M) 17.967ms

16. Pre Compact phase of a Full GC:

[debug][gc,phases,start] GC(3) Pre Compact
...
[debug][gc,phases      ] GC(3) Pre Compact 0.094ms

17. Marking phase of a Full GC:

[info ][gc,phases,start] GC(3) Marking Phase
...
[info ][gc,phases      ] GC(3) Marking Phase 6.809ms

18. Par Mark phase of a Full GC:

[debug][gc,phases,start] GC(3) Par Mark
[debug][gc,phases      ] GC(3) Par Mark 4.935ms

19. Reference Processing phase of a Full GC:

[debug][gc,phases,start] GC(3) Reference Processing
...
[debug][gc,phases      ] GC(3) Reference Processing 0.200ms

20. Weak Processing phase of a Full GC:

[0.544s][debug][gc,phases,start] GC(3) Weak Processing
...
[0.544s][debug][gc,phases      ] GC(3) Weak Processing 0.013ms

21. Class Unloading phase of a Full GC:

[0.544s][debug][gc,phases,start] GC(3) Class Unloading
[0.545s][debug][gc,phases      ] GC(3) Class Unloading 0.786ms

22. ClassLoaderData phase of a Full GC:

[0.544s][debug][gc,phases,start] GC(3) ClassLoaderData
[0.544s][debug][gc,phases      ] GC(3) ClassLoaderData 0.013ms

23. ResolvedMethodTable phase of a Full GC:

[0.544s][debug][gc,phases,start] GC(3) ResolvedMethodTable
[0.544s][debug][gc,phases      ] GC(3) ResolvedMethodTable 0.009ms

24. Scrub String phase of a Full GC:

[0.545s][debug][gc,phases,start] GC(3) Scrub String Table
[0.545s][debug][gc,phases      ] GC(3) Scrub String Table 0.063ms

25. Scrub Symbol phase of a Full GC:

[0.545s][debug][gc,phases,start] GC(3) Scrub Symbol Table
[0.545s][debug][gc,phases      ] GC(3) Scrub Symbol Table 0.706ms

26. Summary phase of a Full GC:

[0.545s][info ][gc,phases,start] GC(3) Summary Phase
[0.545s][info ][gc,phases      ] GC(3) Summary Phase 0.008ms

27. Adjust Roots phase of a Full GC:

[0.545s][info ][gc,phases,start] GC(3) Adjust Roots
[0.547s][info ][gc,phases      ] GC(3) Adjust Roots 1.611ms

28. Compaction phase of a Full GC:

[0.547s][info ][gc,phases,start] GC(3) Compaction Phase
[0.556s][info ][gc,phases      ] GC(3) Compaction Phase 9.026ms

29. Post Compact phase of a Full GC:

[0.556s][info ][gc,phases,start] GC(3) Post Compact
[0.556s][info ][gc,phases      ] GC(3) Post Compact 0.200ms

20. Thread report of a Full GC:

[0.557s][debug][gc,task,time] GC(3) GC-Thread 0 entries: 24
[0.557s][debug][gc,task,time] GC(3) [ noop task 1047784 1047785 ]
[0.557s][debug][gc,task,time] GC(3) [ mark-from-roots-task 1047918 ... ]
[0.557s][debug][gc,task,time] GC(3) [ thread-roots-marking-task ... ]
...
[0.557s][debug][gc,task,time] GC(3) [ thread-roots-marking-task  ... ]
[0.557s][debug][gc,task,time] GC(3) [ mark-from-roots-task 1055931 ... ]
...
[0.557s][debug][gc,task,time] GC(3) [ mark-from-roots-task 1055957 ... ]
[0.557s][debug][gc,task,time] GC(3) [ steal-marking-task 1055957 ... ]
[0.557s][debug][gc,task,time] GC(3) [ waitfor-barrier-task 1057456 ... ]
[0.557s][debug][gc,task,time] GC(3) [ steal-region-task 1064307 ... ]
[0.557s][debug][gc,task,time] GC(3) [ waitfor-barrier-task 1081471 ... ]

[0.557s][debug][gc,task,time] GC(3) GC-Thread 1 entries: 5
[0.557s][debug][gc,task,time] GC(3) [ noop task 1047795 1047799 ]
[0.557s][debug][gc,task,time] GC(3) [ mark-from-roots-task 1047911 ... ]
[0.557s][debug][gc,task,time] GC(3) [ thread-roots-marking-task ... ]
[0.557s][debug][gc,task,time] GC(3) [ steal-marking-task 1057401 ... ]
[0.557s][debug][gc,task,time] GC(3) [ steal-region-task 1064315 ... ]

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