Java GC Tutorials - Herong's Tutorial Examples - v1.11, by Dr. Herong Yang
GC Log Message Examples of Serial Collector
This section provides an example of GC log messages generated from the Serial Collector.
If you run the program again with a given heap size range, you will get more GC log message examples. Below is a list of some GC log messages with my comments:
herong> java -Xms2m -Xmx64m -XX:+UseSerialGC -Xlog:gc,gc+heap=info \ GarbageCollection [0.009s][info][gc] Using Serial [0.055s][info][gc,heap] GC(0) DefNew: 1024K->128K(1152K) [0.055s][info][gc,heap] GC(0) Tenured: 0K->418K(768K) [0.055s][info][gc ] GC(0) Pause Young (Allocation Failure) 1M->0M(1M) 1.188ms -- A Young GC occurred in JVM start-up process Some small objects used by the JVM were deallocated. [0.113s][info][gc ] GC(2) Pause Full (Allocation Failure) 0M->0M(2M) 2.154ms [0.113s][info][gc,heap] GC(1) DefNew: 1152K->0K(1152K) [0.113s][info][gc,heap] GC(1) Tenured: 418K->913K(1524K) [0.113s][info][gc ] GC(1) Pause Young (Allocation Failure) 1M->0M(2M) 3.419ms -- A Young GC followed by a Full GC occurred in JVM start-up process More objects needed by the JVM Heap size increased from 1M to 2M This Full GC is unnecessary, JVM should be started with a larger heap [0.151s][info][gc,heap] GC(3) DefNew: 1023K->127K(1152K) [0.151s][info][gc,heap] GC(3) Tenured: 913K->1205K(1524K) [0.151s][info][gc ] GC(3) Pause Young (Allocation Failure) 1M->1M(2M) 0.824ms [0.214s][info][gc,heap] GC(4) DefNew: 1151K->128K(1152K) [0.214s][info][gc,heap] GC(4) Tenured: 1205K->1447K(1524K) [0.214s][info][gc ] GC(4) Pause Young (Allocation Failure) 2M->1M(2M) 1.110ms [0.257s][info][gc ] GC(6) Pause Full (Allocation Failure) 1M->1M(2M) 3.436ms [0.257s][info][gc,heap] GC(5) DefNew: 1152K->31K(1472K) [0.257s][info][gc,heap] GC(5) Tenured: 1447K->1908K(3180K) [0.257s][info][gc ] GC(5) Pause Young (Allocation Failure) 2M->1M(4M) 4.325ms [0.315s][info][gc,heap] GC(7) DefNew: 1344K->127K(1472K) [0.315s][info][gc,heap] GC(7) Tenured: 1908K->2154K(3180K) [0.315s][info][gc ] GC(7) Pause Young (Allocation Failure) 3M->2M(4M) 1.872ms [0.345s][info][gc,heap] GC(8) DefNew: 1471K->128K(1472K) [0.345s][info][gc,heap] GC(8) Tenured: 2154K->2762K(3180K) [0.345s][info][gc ] GC(8) Pause Young (Allocation Failure) 3M->2M(4M) 2.072ms [0.368s][info][gc,heap] GC(9) DefNew: 1472K->128K(1472K) [0.368s][info][gc,heap] GC(9) Tenured: 2762K->3044K(3180K) [0.368s][info][gc ] GC(9) Pause Young (Allocation Failure) 4M->3M(4M) 1.625ms [0.387s][info][gc ] GC(11) Pause Full (Allocation Failure) 3M->3M(4M) 9.019ms [0.387s][info][gc,heap] GC(10) DefNew: 1472K->1K(2560K) [0.387s][info][gc,heap] GC(10) Tenured: 3044K->3371K(5620K) [0.387s][info][gc ] GC(10) Pause Young (Allocation Failure) 4M->3M(7M) 9.989ms [0.430s][info][gc,heap] GC(12) DefNew: 2304K->256K(2560K) [0.430s][info][gc,heap] GC(12) Tenured: 3371K->3425K(5620K) [0.430s][info][gc ] GC(12) Pause Young (Allocation Failure) 5M->3M(7M) 3.530ms [0.461s][info][gc,heap] GC(13) DefNew: 2560K->256K(2560K) [0.461s][info][gc,heap] GC(13) Tenured: 3425K->3789K(5620K) [0.461s][info][gc ] GC(13) Pause Young (Allocation Failure) 5M->3M(7M) 2.481ms Step/TotalMemory/FreeMemory/UsedMemory: -- More Young GC and Full GC occurred in JVM start-up process They are unnecessary, JVM should be started with a larger heap
[0.510s][info][gc,heap] GC(14) DefNew: 2383K->255K(2560K) [0.510s][info][gc,heap] GC(14) Tenured: 3789K->4308K(5620K) [0.510s][info][gc ] GC(14) Pause Young (Allocation Failure) 6M->4M(7M) 2.915ms 1 8376320 2582304 5794016 -- Another Young GC occurred due to my first 1MB object request Maybe it was too big to fit into the Survivor Space "From". [0.538s][info][gc ] GC(16) Pause Full (Allocation Failure) 6M->3M(8M) 6.827ms [0.538s][info][gc,heap] GC(15) DefNew: 2401K->0K(3136K) [0.538s][info][gc,heap] GC(15) Tenured: 4308K->4065K(6776K) [0.538s][info][gc ] GC(15) Pause Young (Allocation Failure) 6M->3M(9M) 8.840ms 2 10149888 5360456 4789432 -- A Young GC followed by a Full GC occurred due to my 2nd object Heap size increased from 8M to 9M 3 10149888 4265400 5884488 4 10149888 3170344 6979544 [0.540s][info][gc,heap] GC(17) DefNew: 2750K->319K(3136K) [0.540s][info][gc,heap] GC(17) Tenured: 4065K->6449K(6776K) [0.540s][info][gc ] GC(17) Pause Young (Allocation Failure) 6M->6M(9M) 0.876ms 5 10149888 2065688 8084200 -- Another Young GC occurred due to my 3rd and 4th objects Survivor Space "From" was expanded to hold 2 1MB objects 6 10149888 969912 9179976 [0.548s][info][gc ] GC(19) Pause Full (Allocation Failure) 9M->9M(12M) 6.105ms [0.548s][info][gc,heap] GC(18) DefNew: 3027K->319K(6912K) [0.548s][info][gc,heap] GC(18) Tenured: 6449K->9106K(15180K) [0.548s][info][gc ] GC(18) Pause Young (Allocation Failure) 9M->9M(21M) 7.593ms 7 22622208 12393368 10228840 8 22622208 11292448 11329760 9 22622208 10191528 12430680 10 22622208 9090608 13531600 11 22622208 7989688 14632520 [0.554s][info][gc,heap] GC(20) DefNew: 6208K->703K(6912K) [0.554s][info][gc,heap] GC(20) Tenured: 9106K->14578K(15180K) [0.554s][info][gc ] GC(20) Pause Young (Allocation Failure) 14M->14M(21M) 4.421ms 12 22622208 6906968 15715240 13 22622208 5744264 16877944 14 22622208 4704136 17918072 15 22622208 3582056 19040152 16 22622208 2476376 20145832 17 22622208 1370696 21251512 [0.567s][info][gc ] GC(22) Pause Full (Allocation Failure) 20M->20M(26M) 7.839ms [0.567s][info][gc,heap] GC(21) DefNew: 6686K->703K(15488K) [0.567s][info][gc,heap] GC(21) Tenured: 14578K->20516K(34196K) [0.567s][info][gc ] GC(21) Pause Young (Allocation Failure) 20M->20M(48M) 11.604ms 18 50876416 28544296 22332120 19 50876416 27351376 23525040 20 50876416 26224008 24652408 21 50876416 25162192 25714224 22 50876416 24034824 26841592 23 50876416 22956608 27919808 24 50876416 21829240 29047176 25 50876416 20767424 30108992 26 50876416 19640056 31236360 27 50876416 18561840 32314576 28 50876416 17434472 33441944 29 50876416 16372656 34503760 [0.579s][info][gc,heap] GC(23) DefNew: 13690K->1663K(15488K) [0.579s][info][gc,heap] GC(23) Tenured: 20516K->32421K(34196K) [0.579s][info][gc ] GC(23) Pause Young (Allocation Failure) 33M->33M(48M) 8.423ms -- More Young GC and Full GC occurred Heap size was expanded more and more More application 1MB objects can be allocated with GC interruptions. ...
Table of Contents
Heap Memory Area and Size Control
JVM Garbage Collection Logging
Introduction of Garbage Collectors
►Serial Collector - "+XX:+UseSerialGC"
GC Log Message Format for Serial Collector
►GC Log Message Examples of Serial Collector
Log Message Types from Serial Collector
Serial Collector Stops Application for Minor/Major GC
Usage Report on Heap Memory Areas
Default NewRatio - Old vs. New Generation
"-XX:NewRatio" - Ratio of Tenured and "new" Generation
"-XX:SurvivorRatio" - Ratio of Eden and Survivor Space
Serial GC Tracing - Tight Heap
Serial GC Tracing - Tight Heap (Part 2)
Serial GC Tracing - Tight Heap (Part 3)
Serial GC Tracing - Plenty of Heap
Serial GC Tracing - Aged Live Objects
Serial GC Tracing - Tenuring Threshold
"-XX:TargetSurvivorRatio" - Second Tenuring Condition
Serial GC Tracing - Tenuring Threshold Controlled
"-XX:+NeverTenure" and "-XX:+AlwaysTenure" Working
Minor GC Triggering Condition of Serial Collector
Parallel Collector - "+XX:+UseParallelGC"
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