GC Log Message Format for Serial Collector

This section provides explanations on GC log messages generated from the Serial Collector.

The first step to help us understand how Serial Collector works is to understand the GC log messages generated from the Serial Collector.

Let's capture some GC log messages with my sample program, GarbageCollection.java:

herong> \progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m -XX:+UseSerialGC \
   -XX:+PrintGCDetails -XX:+PrintGCTimeStamps GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:

0.102: [GC (Allocation Failure)
      0.102: [DefNew: 649K->64K(960K), 0.0008674 secs]
      649K->505K(1984K), 0.0009833 secs]


1   2031616   697016   1334600
...

Okay. We got our first GC log message from the Serial Collector at 0.102 seconds after the application have started. Here are explanations for every components of the log message:

Continue with additional output in the console:

...
1.055: [GC (Allocation Failure)
      1.055: [DefNew: 861K->64K(960K), 0.0008510 secs]
      1.056: [Tenured: 1226K->1279K(1280K), 0.0009817 secs]
      1303K->1290K(2240K),
      [Metaspace: 44K->44K(4480K)],
      0.0019995 secs]

...

This log message indicates a Full Collection in the Heap (both Young Generation and Tenured Generation). It also did a Method Area (Metaspace) garbage collection. The Full Collection log is larger than the Minor Collection log and contains additional information:

The table below summarizes different types of information included in a GC log message:

[GC (Allocation Failure)
     ^- GC reason

           v- GC type - Young Generation
   1.055: [DefNew: 861K->64K(960K), 0.0008510 secs]
   ^               ^     ^   ^      ^- Time spent on GC
   ^               ^     ^   ^- Total area size
   ^               ^     ^- Object size after GC
   ^- Timestamp    ^- Object size before GC

           v- GC type - Tenured Generation
   1.056: [Tenured: 1226K->1279K(1280K), 0.0009817 secs]

    v- Heap Summary
   1303K->1290K(2240K),
   ^      ^     ^- Total area size
   ^      ^- Object size after GC
   ^- Object size before GC

    v- GC type - Method Area (Metaspace)
   [Metaspace: 44K->44K(4480K)],

    v- Total time spent on the entire GC operation
   0.0019995 secs]

    v- CPU time report of the entire GC operation
[Times: user=0.00 sys=0.00, real=0.00 secs]
        ^         ^         ^- Elapsed time
        ^         ^- CPU time spent on OS kernel
        ^- CPU time spent on JVM

Table of Contents

 About This Book

 Heap Memory Area and Size Control

 JVM Garbage Collection Logging

 Introduction of Garbage Collectors

Serial Collector - "+XX:+UseSerialGC"

 What Is Serial Collector

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 - 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" not 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"

 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

 Archived Tutorials

 References

 Full Version in PDF/EPUB