GC Log Message Format for Serial Collector

Java 8 GC Tutorials - Herong's Tutorial Examples

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

"0.102:" - Timestamp in seconds relative to the JVM start time.
"[GC (Allocation Failure) ...]" - Header of the GC (Garbage Collection) message with the reason code "Allocation Failure" for the GC. So you can read this example as "A GC is performed because of Allocation Failure."
"0.102: [DefNew: 649K->64K(960K), 0.0008674 secs]" - Young Generation GC record with the timestamp in seconds relative the JVM start time, the total object size in the Young Generation before GC, the total object size after GC, and the current total memory size and time spent on the GC. So you can read this example as "A Young Generation GC was performed at 0.102 seconds since the JVM started. It released 585K of space by removing dead objects and promoting older objects to the Tenured Generation, reduced the total object size from 649K to 64K in the Young Generation, and took 0.0008674 seconds. The total memory size of the Young Generation was 960K at the time of the GC." "DefNew (Default New)" is the internal name of the Serial Collector.
"... 649K->505K(1984K), ..." - GC summary at the Heap level, including both Young Generation and Tenured Generation, with the total object size in the Heap before GC, the total object size after GC, and the current total memory size of the Heap. So you can read this example as "The GC released 144 of dead objects, reduced the total object size from 649K to 505K in the Heap. The total memory size of the Heap was 1984K at the time of the GC."
"... 0.0009833 secs]" - Total time in seconds spent on the entire GC operation, including Young Generation GC, Tenured Generation GC and Method Area GC. So you can read this example as "0.0009833 seconds spent on the entire GC operation."
"[Times: user=0.00 sys=0.00, real=0.00 secs]" - CPU time report of the entire GC operation with CPU time spent on the JVM (user), CPU time spent on the OS kernel (system), and elapsed time of the GC. Note that CPU time could be higher than elapsed time, if multiple CPUs were used. All times are in unit of seconds and truncated with 2 decimal points. So you can read this example as "0.00 CPU seconds spent on the JVM, 0.00 CPU seconds spent on OS kernel. The entire GC took 0.00 seconds."

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:

"1.056: [Tenured: 1226K->1279K(1280K), 0.0009817 secs]" - Tenured Generation GC record with the timestamp in seconds relative the JVM start time, the total object size in the Tenured Generation before GC, the total object size after GC, and the current total memory size and time spent on the GC. So you can read this example as "A Tenured Generation GC was performed at 1.056 seconds since the JVM started. The total object size increased by 53K from 1226K to 1279K, because older objects promoted from the Young Generation into the Tenured Generation. The Tenured Generation GC took 0.0009817 seconds. The total memory size of the Tenured Generation was 1280K at the time of the GC." "Tenured" is the internal name of the Serial Collector.
"[Metaspace: 44K->44K(4480K)]" - Method Area (also called Meta Space) GC, which always performed at the same time as the Tenured Generation GC) record with the total object size in the Method Area before GC, the total object size after GC, and the current total memory size of the Method Area. So you can read this example as "A Method Area GC was performed at the same time as the Tenured Generation GC. The total object size was 44K and did not change, because there was no dead objects. The total memory size of the Method Area was 4480K at the time of the GC."

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