Understanding GC Logging
Disclaimer: Links contained herein to an external website(s) are provided for convenience only. Red Hat has not reviewed the links and is not responsible for the content or its availability. The inclusion of any link to an external website does not imply endorsement by Red Hat of the website or their entities, products or services. You agree that Red Hat is not responsible or liable for any loss or expenses that may result due to your use of (or reliance on) the external site or content.
Introduction
Obtaining garbage collection, or GC, logs from a JVM is often a necessary step in understanding a JVM's health and troubleshooting any performance issues. These logs are often required to begin optimizing a JVM as they allow insight into each generation's occupancy and can indicate issues at the JVM layer or lower.
Enabling GC Logging
GC logging can be enabled by adjusting the JVM options in use and then restarting the JVM; see the section appropriate to your JDK below:
OpenJDK / Sun JDK later than 1.6 update 4
-verbose:gc -Xloggc:gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCDateStamps
IBM JDK
-verbose:gc -Xverbosegclog:gc.log.`date +%Y%m%d%H%M%S`
With either of the above a gc.log file including the date will be created each time the JVM is started; without the date specified as part of the path these logs will be overwritten on any subsequent restarts.
For full instructions, including other JDKs and options, reference How do I enable Java garbage collection logging?.
How Garbage Collections Work
Explaining the full GC process is beyond the scope of this article; however, it is important to understand how the heap is structured as this is key to comprehending the log files.
A Java heap is divided into three primary regions, of which we will primarily focus on the first two:
- The Young Generation - When an object is newly created it is placed in this region. After this space is filled a minor collection occurs.
- The Old Generation - After an object has survived a certain number of minor collections it is placed into this region. When this generation is full a major collection occurs.
- The Permanent Generation - Separate from the other two regions, this generation contains classes and static content. A
Full GCis required to reclaim memory from this section.
These collections are discussed below:
Minor Collection: These collections occur when the Young Generation is full, and are expected to happen frequently over the lifespan of the JVM. This collection will remove any unreferenced objects in the Young Generation, along with promoting any objects that have survived enough collections to the Old Generation.
Major Collection: Also known as a Full GC, this collection occurs when the Old Generation is full, and will consist of a Minor Collection along with removing any unreferenced objects in the Old and Permanent Generations. These are expected to occur, and do not indicate an issue.
In addition to the above there are other collection types for separate collection policies, such as CMS and G1.
Understanding the log
Each line in the GC log represents a single collection, showing the amount of memory both before and after the collection completed, along with the amount of time taken broken down by where it was spent.
A single entry will appear similar to the following:
2014-11-07T05:04:13.460+0100: 7.253: [GC [PSYoungGen: 131072K->17216K(152896K)] 131072K->17224K(502464K), 0.0366910 secs] [Times: user=0.06 sys=0.01, real=0.04 secs]
This line is broken down into its components below:
| Entry | Meaning |
|---|---|
| 2014-11-07T05:04:13.460+0100 | Shows the time that the collection occurred. Will only appear if -XX:+PrintGCDateStamps is enabled. |
| 7.253 | Number of seconds since the JVM was started. Will only appear if -XX:+PrintGCTimeStamps is enabled. |
| [GC | The type of collection. As Full is not listed this is a minor collection. |
| [PSYoungGen: | The generation being collected. |
| 131072K->17216K(152896K) | These values show the initial memory, the memory usage after a collection has completed, and the maximum memory size for a generation. If the values are listed without an accompanying generation it represents the total heap space. |
| 0.0366910 secs | The time taken to complete the collection. |
| [Times: user=0.06 sys=0.01, real=0.04 secs] | This shows the time broken down into its corresponding parts. |
The values for times relate to where the GC's cycles were being spent:
| Descriptor | Meaning |
|---|---|
| Sys | Amount of cpu time spent in the Content from www.linfo.org is not included.Kernel_Mode within the executing process i.e I/O, swapping program from/to memory. |
| User | Amount of cpu spent in Content from www.linfo.org is not included.User_Mode code outside the kernel. |
| Real | The time taken if you were using a stop watch/clock. This is how long the JVM was paused. |
A full collection will include the word Full near the beginning of the entry, as shown below:
3214.214: [Full GC [...]
When System is present in a collection it indicates that this GC was manually triggered was opposed to being caused by the heap becoming full. In the below snippet we see this appearing before any of the generation information is printed:
2014-11-07T06:05:17.431+0100: [Full GC (System) [...]
It is typically recommended to prevent these from occurring in production environments by adding -XX:+DisableExplicitGC to the JVM arguments.
Example
Consider the following entry:
2014-11-07T05:05:14.844+0100: 68.637: [Full GC [PSYoungGen: 48810K->0K(574656K)] [ParOldGen: 485464K->399146K(719616K)] 534274K->399146K(1294272K) [PSPermGen: 192422K->156245K(393216K)], 2.5184890 secs] [Times: user=4.52 sys=0.03, real=2.51 secs]
In this line we can see that the JVM was paused for 2.51 seconds, as this is the real time logged. During this time 48 MB were reclaimed from the Young Generation, as it was reduced from 48810K to 0K. The Old Generation reclaimed ~85 MB, as it went from 485464K to 399146K. The entire heap went from ~534 MB down to ~400 MB, and can hold up to ~1.3 GB, or 1294272K at present.