Java GC Tutorials - Herong's Tutorial Examples - v1.12, by Herong Yang
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 Young 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
Heap Memory Area and Size Control
JVM Garbage Collection Logging
Introduction of Garbage Collectors
Serial Collector - "+XX:+UseSerialGC"
►Parallel Collector - "+XX:+UseParallelGC"
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