"-XX:+PrintGCDetails" - Garbage Collection Logging

JVM Tutorials - Herong's Tutorial Examples

∟Memory Management and Garbage Collectors

∟"-XX:+PrintGCDetails" - Garbage Collection Logging

This section describes HotSpot JVM options to generate garbage collection logging messages. It also describes log message format to help us understand what the JVM is telling us.

Now we have a good idea of what is Serial Collector, and how it works. Let's see if we watch it doing the memory management job for my sample application, GarbageCollection.java.

To do this, we are going to use some HotSpot command line options related to garbage collection logging:

-XX:+UseSerialGC - Force HotSpot to use Serial Collector.
-XX:+PrintGC - Print a shot message after each garbage collection is done.
-verbose:gc - Same as "-XX:+PrintGC".
-XX:+PrintGCDetails - Print a long message with more details after each garbage collection is done.
-XX:+PrintGCTimeStamps - Print a timestamp relative to the JVM start time when a garbage collection occurs.
-XX:+PrintGCDateStamps - Print a calendar data and timestamp when a garbage collection occurs.
-Xloggc:<file> - Force garbage collection message to be logged into a file instead of the console.

Now let's try it with HotSpot 1.8:

C:\herong>\progra~1\java\jdk1.8.0\bin\javac GarbageCollection.java

C:\>\progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m -XX:+UseSerialGC
   -XX:+PrintGCDetails GarbageCollection
Step/TotalMemory/FreeMemory/UsedMemory:
   [GC (Allocation Failure) 
      0.054: [DefNew: 649K->64K(960K), 0.0008674 secs] 
      649K->505K(1984K), 0.0009833 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
1   2031616   697016   1334600
...

Okay. We got our first log message, which indicates a Minor Collection, from the Serial Collector. We need to understand the format of the message first to be able to read the it:

"[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.054: [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.054 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."
"... 649K->505K(1984K), ..." - GC summary at the Heap, 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:

...
   [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] 
   [Times: user=0.00 sys=0.00, real=0.00 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."
"[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 aftter 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 aftter 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

When Java application is ended or terminated, the JVM also generate a memory usage summary in the GC log:

Heap
 def new generation   total 19648K, used 8770K [0x03c00000, 0x051...
  eden space 17472K,  50% used [0x03c00000, 0x04490bb0, 0x04d1000...
  from space 2176K,   0% used [0x04f30000, 0x04f30000, 0x05150000...
  to   space 2176K,   0% used [0x04d10000, 0x04d10000, 0x04f30000...
 tenured generation   total 43712K, used 32730K [0x05150000, 0x07...
   the space 43712K,  74% used [0x05150000, 0x07146ba8, 0x07146c0...
 Metaspace used 45K, capacity 2242K, committed 2368K, reserved 4480K

Now we now how big each data area is and how much space was actually used in each area.

Last update: 2014.

Table of Contents

About This Book

Downloading and Installing JDK 1.8.0 on Windows

Downloading and Installing JDK 1.7.0 on Windows

java.lang.Runtime Class - The JVM Instance

java.lang.System Class - The Operating System

ClassLoader Class - Class Loaders

Class Class - Class Reflections

Sun's JVM - Java HotSpot VM

JRockit JVM 28.2.7 by Oracle Corporation